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

5 6
// @dart = 2.8

7
import 'dart:async';
8

9
import 'package:meta/meta.dart';
10
import 'package:vm_service/vm_service.dart' as vm_service;
11

12
import 'base/common.dart';
13
import 'base/error_handling_io.dart';
14
import 'base/file_system.dart';
15
import 'base/logger.dart';
16 17 18 19
import 'base/utils.dart';
import 'vmservice.dart';

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

class Tracing {
26 27 28 29
  Tracing({
    @required this.vmService,
    @required Logger logger,
  }) : _logger = logger;
30

31
  static const String firstUsefulFrameEventName = kFirstFrameRasterizedEventName;
32

33
  final FlutterVmService vmService;
34
  final Logger _logger;
35

36
  Future<void> startTracing() async {
37
    await vmService.setTimelineFlags(<String>['Compiler', 'Dart', 'Embedder', 'GC']);
38
    await vmService.service.clearVMTimeline();
39 40 41 42
  }

  /// Stops tracing; optionally wait for first frame.
  Future<Map<String, dynamic>> stopTracingAndDownloadTimeline({
43
    bool awaitFirstFrame = false,
44
  }) async {
45
    if (awaitFirstFrame) {
46
      final Status status = _logger.startProgress(
47
        'Waiting for application to render first frame...',
48
      );
49 50
      try {
        final Completer<void> whenFirstFrameRendered = Completer<void>();
51
        try {
52
          await vmService.service.streamListen(vm_service.EventStreams.kExtension);
53 54 55 56
        } on vm_service.RPCError {
          // It is safe to ignore this error because we expect an error to be
          // thrown if we're already subscribed.
        }
57
        vmService.service.onExtensionEvent.listen((vm_service.Event event) {
58 59
          if (event.extensionKind == 'Flutter.FirstFrame') {
            whenFirstFrameRendered.complete();
60 61 62
          }
        });
        bool done = false;
63 64 65
        final List<FlutterView> views = await vmService.getFlutterViews();
        for (final FlutterView view in views) {
          if (await vmService
66 67 68
              .flutterAlreadyPaintedFirstUsefulFrame(
                isolateId: view.uiIsolate.id,
              )) {
69 70 71 72
            done = true;
            break;
          }
        }
73
        if (!done) {
74
          await whenFirstFrameRendered.future;
75
        }
76 77
      // The exception is rethrown, so don't catch only Exceptions.
      } catch (exception) { // ignore: avoid_catches_without_on_clauses
78 79 80 81
        status.cancel();
        rethrow;
      }
      status.stop();
82
    }
83 84 85 86 87 88 89
    final vm_service.Response timeline = await vmService.getTimeline();
    await vmService.setTimelineFlags(<String>[]);
    if (timeline == null) {
      throwToolExit(
        'The device disconnected before the timeline could be retrieved.',
      );
    }
90
    return timeline.json;
91 92 93 94
  }
}

/// Download the startup trace information from the given observatory client and
95
/// store it to `$output/start_up_info.json`.
96
Future<void> downloadStartupTrace(FlutterVmService vmService, {
97 98 99 100 101
  bool awaitFirstFrame = true,
  @required Logger logger,
  @required Directory output,
}) async {
  final File traceInfoFile = output.childFile('start_up_info.json');
102 103

  // Delete old startup data, if any.
104
  ErrorHandlingFileSystem.deleteIfExists(traceInfoFile);
105 106

  // Create "build" directory, if missing.
107 108 109
  if (!traceInfoFile.parent.existsSync()) {
    traceInfoFile.parent.createSync();
  }
110

111
  final Tracing tracing = Tracing(vmService: vmService, logger: logger);
112 113

  final Map<String, dynamic> timeline = await tracing.stopTracingAndDownloadTimeline(
114
    awaitFirstFrame: awaitFirstFrame,
115 116
  );

117 118 119
  final File traceTimelineFile = output.childFile('start_up_timeline.json');
  traceTimelineFile.writeAsStringSync(toPrettyJson(timeline));

120
  int extractInstantEventTimestamp(String eventName) {
121
    final List<Map<String, dynamic>> events =
122
        List<Map<String, dynamic>>.from(timeline['traceEvents'] as List<dynamic>);
123
    final Map<String, dynamic> event = events.firstWhere(
124
      (Map<String, dynamic> event) => event['name'] == eventName, orElse: () => null,
125
    );
126
    return event == null ? null : (event['ts'] as int);
127 128
  }

129 130
  String message = 'No useful metrics were gathered.';

131 132
  final int engineEnterTimestampMicros = extractInstantEventTimestamp(kFlutterEngineMainEnterEventName);
  final int frameworkInitTimestampMicros = extractInstantEventTimestamp(kFrameworkInitEventName);
133 134

  if (engineEnterTimestampMicros == null) {
135 136
    logger.printTrace('Engine start event is missing in the timeline: $timeline');
    throwToolExit('Engine start event is missing in the timeline. Cannot compute startup time.');
137 138 139 140 141 142 143
  }

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

  if (frameworkInitTimestampMicros != null) {
144 145 146 147 148 149
    final int timeToFrameworkInitMicros = frameworkInitTimestampMicros - engineEnterTimestampMicros;
    traceInfo['timeToFrameworkInitMicros'] = timeToFrameworkInitMicros;
    message = 'Time to framework init: ${timeToFrameworkInitMicros ~/ 1000}ms.';
  }

  if (awaitFirstFrame) {
150 151
    final int firstFrameBuiltTimestampMicros = extractInstantEventTimestamp(kFirstFrameBuiltEventName);
    final int firstFrameRasterizedTimestampMicros = extractInstantEventTimestamp(kFirstFrameRasterizedEventName);
152
    if (firstFrameBuiltTimestampMicros == null || firstFrameRasterizedTimestampMicros == null) {
153 154
      logger.printTrace('First frame events are missing in the timeline: $timeline');
      throwToolExit('First frame events are missing in the timeline. Cannot compute startup time.');
155
    }
156 157 158 159 160 161 162

    // 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;
163 164
    traceInfo['timeToFirstFrameMicros'] = timeToFirstFrameMicros;
    message = 'Time to first frame: ${timeToFirstFrameMicros ~/ 1000}ms.';
165
    if (frameworkInitTimestampMicros != null) {
166
      traceInfo['timeAfterFrameworkInitMicros'] = firstFrameBuiltTimestampMicros - frameworkInitTimestampMicros;
167
    }
168 169 170 171
  }

  traceInfoFile.writeAsStringSync(toPrettyJson(traceInfo));

172 173
  logger.printStatus(message);
  logger.printStatus('Saved startup trace info in ${traceInfoFile.path}.');
174
}