tracing.dart 6.23 KB
Newer Older
Ian Hickson's avatar
Ian Hickson committed
1
// Copyright 2014 The Flutter Authors. All rights reserved.
2 3 4 5
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

import 'dart:async';
6
import 'package:vm_service/vm_service.dart' as vm_service;
7 8

import 'base/file_system.dart';
9
import 'base/logger.dart';
10 11
import 'base/utils.dart';
import 'build_info.dart';
12
import 'globals.dart' as globals;
13 14 15
import 'vmservice.dart';

// Names of some of the Timeline events we care about.
16 17 18 19
const String kFlutterEngineMainEnterEventName = 'FlutterEngineMainEnter';
const String kFrameworkInitEventName = 'Framework initialization';
const String kFirstFrameBuiltEventName = 'Widgets built first useful frame';
const String kFirstFrameRasterizedEventName = 'Rasterized first useful frame';
20 21 22 23

class Tracing {
  Tracing(this.vmService);

24
  static const String firstUsefulFrameEventName = kFirstFrameRasterizedEventName;
25

26
  static Future<Tracing> connect(Uri uri) async {
27
    final vm_service.VmService observatory = await connectToVmService(uri);
28
    return Tracing(observatory);
29 30
  }

31
  final vm_service.VmService vmService;
32

33
  Future<void> startTracing() async {
34 35
    await vmService.setVMTimelineFlags(<String>['Compiler', 'Dart', 'Embedder', 'GC']);
    await vmService.clearVMTimeline();
36 37 38 39
  }

  /// Stops tracing; optionally wait for first frame.
  Future<Map<String, dynamic>> stopTracingAndDownloadTimeline({
40
    bool awaitFirstFrame = false,
41
  }) async {
42
    if (awaitFirstFrame) {
43
      final Status status = globals.logger.startProgress(
44
        'Waiting for application to render first frame...',
45
        timeout: timeoutConfiguration.fastOperation,
46
      );
47 48
      try {
        final Completer<void> whenFirstFrameRendered = Completer<void>();
49 50
        await vmService.streamListen('Extension');
        vmService.onExtensionEvent.listen((vm_service.Event event) {
51 52
          if (event.extensionKind == 'Flutter.FirstFrame') {
            whenFirstFrameRendered.complete();
53 54 55
          }
        });
        bool done = false;
56 57 58
        final List<FlutterView> views = await vmService.getFlutterViews();
        for (final FlutterView view in views) {
          if (await vmService
59 60 61
              .flutterAlreadyPaintedFirstUsefulFrame(
                isolateId: view.uiIsolate.id,
              )) {
62 63 64 65
            done = true;
            break;
          }
        }
66
        if (!done) {
67
          await whenFirstFrameRendered.future;
68
        }
69 70
      // The exception is rethrown, so don't catch only Exceptions.
      } catch (exception) { // ignore: avoid_catches_without_on_clauses
71 72 73 74
        status.cancel();
        rethrow;
      }
      status.stop();
75
    }
76 77 78
    final vm_service.Timeline timeline = await vmService.getVMTimeline();
    await vmService.setVMTimelineFlags(<String>[]);
    return timeline.json;
79 80 81 82 83
  }
}

/// Download the startup trace information from the given observatory client and
/// store it to build/start_up_info.json.
84
Future<void> downloadStartupTrace(vm_service.VmService vmService, { bool awaitFirstFrame = true }) async {
85 86
  final String traceInfoFilePath = globals.fs.path.join(getBuildDirectory(), 'start_up_info.json');
  final File traceInfoFile = globals.fs.file(traceInfoFilePath);
87 88

  // Delete old startup data, if any.
89 90 91
  if (traceInfoFile.existsSync()) {
    traceInfoFile.deleteSync();
  }
92 93

  // Create "build" directory, if missing.
94 95 96
  if (!traceInfoFile.parent.existsSync()) {
    traceInfoFile.parent.createSync();
  }
97

98
  final Tracing tracing = Tracing(vmService);
99 100

  final Map<String, dynamic> timeline = await tracing.stopTracingAndDownloadTimeline(
101
    awaitFirstFrame: awaitFirstFrame,
102 103 104
  );

  int extractInstantEventTimestamp(String eventName) {
105
    final List<Map<String, dynamic>> events =
106
        List<Map<String, dynamic>>.from(timeline['traceEvents'] as List<dynamic>);
107
    final Map<String, dynamic> event = events.firstWhere(
108
      (Map<String, dynamic> event) => event['name'] == eventName, orElse: () => null,
109
    );
110
    return event == null ? null : (event['ts'] as int);
111 112
  }

113 114
  String message = 'No useful metrics were gathered.';

115 116
  final int engineEnterTimestampMicros = extractInstantEventTimestamp(kFlutterEngineMainEnterEventName);
  final int frameworkInitTimestampMicros = extractInstantEventTimestamp(kFrameworkInitEventName);
117 118

  if (engineEnterTimestampMicros == null) {
119
    globals.printTrace('Engine start event is missing in the timeline: $timeline');
120 121 122 123 124 125 126 127
    throw 'Engine start event is missing in the timeline. Cannot compute startup time.';
  }

  final Map<String, dynamic> traceInfo = <String, dynamic>{
    'engineEnterTimestampMicros': engineEnterTimestampMicros,
  };

  if (frameworkInitTimestampMicros != null) {
128 129 130 131 132 133
    final int timeToFrameworkInitMicros = frameworkInitTimestampMicros - engineEnterTimestampMicros;
    traceInfo['timeToFrameworkInitMicros'] = timeToFrameworkInitMicros;
    message = 'Time to framework init: ${timeToFrameworkInitMicros ~/ 1000}ms.';
  }

  if (awaitFirstFrame) {
134 135
    final int firstFrameBuiltTimestampMicros = extractInstantEventTimestamp(kFirstFrameBuiltEventName);
    final int firstFrameRasterizedTimestampMicros = extractInstantEventTimestamp(kFirstFrameRasterizedEventName);
136
    if (firstFrameBuiltTimestampMicros == null || firstFrameRasterizedTimestampMicros == null) {
137
      globals.printTrace('First frame events are missing in the timeline: $timeline');
138
      throw 'First frame events are missing in the timeline. Cannot compute startup time.';
139
    }
140 141 142 143 144 145 146

    // To keep our old benchmarks valid, we'll preserve the
    // timeToFirstFrameMicros as the firstFrameBuiltTimestampMicros.
    // Additionally, we add timeToFirstFrameRasterizedMicros for a more accurate
    // benchmark.
    traceInfo['timeToFirstFrameRasterizedMicros'] = firstFrameRasterizedTimestampMicros - engineEnterTimestampMicros;
    final int timeToFirstFrameMicros = firstFrameBuiltTimestampMicros - engineEnterTimestampMicros;
147 148
    traceInfo['timeToFirstFrameMicros'] = timeToFirstFrameMicros;
    message = 'Time to first frame: ${timeToFirstFrameMicros ~/ 1000}ms.';
149
    if (frameworkInitTimestampMicros != null) {
150
      traceInfo['timeAfterFrameworkInitMicros'] = firstFrameBuiltTimestampMicros - frameworkInitTimestampMicros;
151
    }
152 153 154 155
  }

  traceInfoFile.writeAsStringSync(toPrettyJson(traceInfo));

156 157
  globals.printStatus(message);
  globals.printStatus('Saved startup trace info in ${traceInfoFile.path}.');
158
}