tracing.dart 8.45 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

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

9
import 'base/common.dart';
10
import 'base/error_handling_io.dart';
11
import 'base/file_system.dart';
12
import 'base/logger.dart';
13
import 'base/utils.dart';
14
import 'convert.dart';
15 16 17
import 'vmservice.dart';

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

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

29
  static const String firstUsefulFrameEventName = kFirstFrameRasterizedEventName;
30

31
  final FlutterVmService vmService;
32
  final Logger _logger;
33

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

  /// Stops tracing; optionally wait for first frame.
40
  Future<Map<String, Object?>> stopTracingAndDownloadTimeline({
41
    bool awaitFirstFrame = false,
42
  }) async {
43
    if (awaitFirstFrame) {
44
      final Status status = _logger.startProgress(
45
        'Waiting for application to render first frame...',
46
      );
47 48
      try {
        final Completer<void> whenFirstFrameRendered = Completer<void>();
49
        try {
50
          await vmService.service.streamListen(vm_service.EventStreams.kExtension);
51 52 53 54
        } on vm_service.RPCError {
          // It is safe to ignore this error because we expect an error to be
          // thrown if we're already subscribed.
        }
55 56
        final StringBuffer bufferedEvents = StringBuffer();
        void Function(String) handleBufferedEvent = bufferedEvents.writeln;
57
        vmService.service.onExtensionEvent.listen((vm_service.Event event) {
58
          handleBufferedEvent('${event.extensionKind}: ${event.extensionData}');
59 60
          if (event.extensionKind == 'Flutter.FirstFrame') {
            whenFirstFrameRendered.complete();
61 62 63
          }
        });
        bool done = false;
64 65
        final List<FlutterView> views = await vmService.getFlutterViews();
        for (final FlutterView view in views) {
66 67
          final String? uiIsolateId = view.uiIsolate?.id;
          if (uiIsolateId != null && await vmService
68
              .flutterAlreadyPaintedFirstUsefulFrame(
69
                isolateId: uiIsolateId,
70
              )) {
71 72 73 74
            done = true;
            break;
          }
        }
75
        if (!done) {
76
          final Timer timer = Timer(const Duration(seconds: 10), () async {
77 78
            _logger.printStatus('First frame is taking longer than expected...');
            for (final FlutterView view in views) {
79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94
              final String? isolateId = view.uiIsolate?.id;
              _logger.printTrace('View ID: ${view.id}');
              if (isolateId == null) {
                _logger.printTrace('No isolate ID associated with the view.');
                continue;
              }
              final vm_service.Isolate? isolate = await vmService.getIsolateOrNull(isolateId);
              if (isolate == null) {
                _logger.printTrace('Isolate $isolateId not found.');
                continue;
              }
              _logger.printTrace('Isolate $isolateId state:');
              final Map<String, Object?> isolateState = isolate.toJson();
              // "libraries" has very long output and is likely unrelated to any first-frame issues.
              isolateState.remove('libraries');
              _logger.printTrace(jsonEncode(isolateState));
95 96 97 98 99 100
            }
            _logger.printTrace('Received VM events:');
            _logger.printTrace(bufferedEvents.toString());
            // Swap to just printing new events instead of buffering.
            handleBufferedEvent = _logger.printTrace;
          });
101
          await whenFirstFrameRendered.future;
102
          timer.cancel();
103
        }
104 105
      // The exception is rethrown, so don't catch only Exceptions.
      } catch (exception) { // ignore: avoid_catches_without_on_clauses
106 107 108 109
        status.cancel();
        rethrow;
      }
      status.stop();
110
    }
111
    final vm_service.Response? timeline = await vmService.getTimeline();
112
    await vmService.setTimelineFlags(<String>[]);
113 114
    final Map<String, Object?>? timelineJson = timeline?.json;
    if (timelineJson == null) {
115 116 117 118
      throwToolExit(
        'The device disconnected before the timeline could be retrieved.',
      );
    }
119
    return timelineJson;
120 121 122 123
  }
}

/// Download the startup trace information from the given observatory client and
124
/// store it to `$output/start_up_info.json`.
125
Future<void> downloadStartupTrace(FlutterVmService vmService, {
126
  bool awaitFirstFrame = true,
127 128
  required Logger logger,
  required Directory output,
129 130
}) async {
  final File traceInfoFile = output.childFile('start_up_info.json');
131 132

  // Delete old startup data, if any.
133
  ErrorHandlingFileSystem.deleteIfExists(traceInfoFile);
134 135

  // Create "build" directory, if missing.
136 137 138
  if (!traceInfoFile.parent.existsSync()) {
    traceInfoFile.parent.createSync();
  }
139

140
  final Tracing tracing = Tracing(vmService: vmService, logger: logger);
141

142
  final Map<String, Object?> timeline = await tracing.stopTracingAndDownloadTimeline(
143
    awaitFirstFrame: awaitFirstFrame,
144 145
  );

146 147 148
  final File traceTimelineFile = output.childFile('start_up_timeline.json');
  traceTimelineFile.writeAsStringSync(toPrettyJson(timeline));

149 150 151 152 153 154 155 156 157 158 159 160 161
  int? extractInstantEventTimestamp(String eventName) {
    final List<Object?>? traceEvents = timeline['traceEvents'] as List<Object?>?;
    if (traceEvents == null) {
      return null;
    }
    final List<Map<String, Object?>> events = List<Map<String, Object?>>.from(traceEvents);
    Map<String, Object?>? matchedEvent;
    for (final Map<String, Object?> event in events) {
      if (event['name'] == eventName) {
        matchedEvent = event;
      }
    }
    return matchedEvent == null ? null : (matchedEvent['ts'] as int?);
162 163
  }

164 165
  String message = 'No useful metrics were gathered.';

166 167
  final int? engineEnterTimestampMicros = extractInstantEventTimestamp(kFlutterEngineMainEnterEventName);
  final int? frameworkInitTimestampMicros = extractInstantEventTimestamp(kFrameworkInitEventName);
168 169

  if (engineEnterTimestampMicros == null) {
170 171
    logger.printTrace('Engine start event is missing in the timeline: $timeline');
    throwToolExit('Engine start event is missing in the timeline. Cannot compute startup time.');
172 173
  }

174
  final Map<String, Object?> traceInfo = <String, Object?>{
175 176 177 178
    'engineEnterTimestampMicros': engineEnterTimestampMicros,
  };

  if (frameworkInitTimestampMicros != null) {
179 180 181 182 183 184
    final int timeToFrameworkInitMicros = frameworkInitTimestampMicros - engineEnterTimestampMicros;
    traceInfo['timeToFrameworkInitMicros'] = timeToFrameworkInitMicros;
    message = 'Time to framework init: ${timeToFrameworkInitMicros ~/ 1000}ms.';
  }

  if (awaitFirstFrame) {
185 186
    final int? firstFrameBuiltTimestampMicros = extractInstantEventTimestamp(kFirstFrameBuiltEventName);
    final int? firstFrameRasterizedTimestampMicros = extractInstantEventTimestamp(kFirstFrameRasterizedEventName);
187
    if (firstFrameBuiltTimestampMicros == null || firstFrameRasterizedTimestampMicros == null) {
188 189
      logger.printTrace('First frame events are missing in the timeline: $timeline');
      throwToolExit('First frame events are missing in the timeline. Cannot compute startup time.');
190
    }
191 192 193 194 195 196 197

    // 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;
198 199
    traceInfo['timeToFirstFrameMicros'] = timeToFirstFrameMicros;
    message = 'Time to first frame: ${timeToFirstFrameMicros ~/ 1000}ms.';
200
    if (frameworkInitTimestampMicros != null) {
201
      traceInfo['timeAfterFrameworkInitMicros'] = firstFrameBuiltTimestampMicros - frameworkInitTimestampMicros;
202
    }
203 204 205 206
  }

  traceInfoFile.writeAsStringSync(toPrettyJson(traceInfo));

207 208
  logger.printStatus(message);
  logger.printStatus('Saved startup trace info in ${traceInfoFile.path}.');
209
}