timeline_summary.dart 14 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:convert' show json, JsonEncoder;
8
import 'dart:math' as math;
9 10 11 12 13

import 'package:file/file.dart';
import 'package:path/path.dart' as path;

import 'common.dart';
14 15
import 'percentile_utils.dart';
import 'profiling_summarizer.dart';
16
import 'scene_display_lag_summarizer.dart';
17
import 'timeline.dart';
18

19
const JsonEncoder _prettyEncoder = JsonEncoder.withIndent('  ');
20 21 22

/// The maximum amount of time considered safe to spend for a frame's build
/// phase. Anything past that is in the danger of missing the frame as 60FPS.
23
const Duration kBuildBudget = Duration(milliseconds: 16);
24

25 26 27 28 29 30
/// The name of the framework frame build events we need to filter or extract.
const String kBuildFrameEventName = 'Frame';

/// The name of the engine frame rasterization events we need to filter or extract.
const String kRasterizeFrameEventName = 'GPURasterizer::Draw';

31
/// Extracts statistics from a [Timeline].
32
class TimelineSummary {
33
  /// Creates a timeline summary given a full timeline object.
34
  TimelineSummary.summarize(this._timeline);
35

36
  final Timeline _timeline;
37 38 39

  /// Average amount of time spent per frame in the framework building widgets,
  /// updating layout, painting and compositing.
40
  ///
41
  /// Returns null if no frames were recorded.
42
  double computeAverageFrameBuildTimeMillis() {
43
    return _averageInMillis(_extractFrameDurations());
44 45
  }

46 47 48 49 50 51 52
  /// The [p]-th percentile frame rasterization time in milliseconds.
  ///
  /// Returns null if no frames were recorded.
  double computePercentileFrameBuildTimeMillis(double p) {
    return _percentileInMillis(_extractFrameDurations(), p);
  }

53
  /// The longest frame build time in milliseconds.
54
  ///
55
  /// Returns null if no frames were recorded.
56
  double computeWorstFrameBuildTimeMillis() {
57
    return _maxInMillis(_extractFrameDurations());
58 59
  }

60
  /// The number of frames that missed the [kBuildBudget] and therefore are
61
  /// in the danger of missing frames.
62
  int computeMissedFrameBuildBudgetCount([ Duration frameBuildBudget = kBuildBudget ]) => _extractFrameDurations()
63
    .where((Duration duration) => duration > kBuildBudget)
64 65
    .length;

66
  /// Average amount of time spent per frame in the engine rasterizer.
67
  ///
68
  /// Returns null if no frames were recorded.
69
  double computeAverageFrameRasterizerTimeMillis() {
70
    return _averageInMillis(_extractGpuRasterizerDrawDurations());
71 72 73 74
  }

  /// The longest frame rasterization time in milliseconds.
  ///
75
  /// Returns null if no frames were recorded.
76
  double computeWorstFrameRasterizerTimeMillis() {
77
    return _maxInMillis(_extractGpuRasterizerDrawDurations());
78 79
  }

80 81 82 83
  /// The [p]-th percentile frame rasterization time in milliseconds.
  ///
  /// Returns null if no frames were recorded.
  double computePercentileFrameRasterizerTimeMillis(double p) {
84
    return _percentileInMillis(_extractGpuRasterizerDrawDurations(), p);
85 86
  }

87 88
  /// The number of frames that missed the [kBuildBudget] on the raster thread
  /// and therefore are in the danger of missing frames.
89 90
  int computeMissedFrameRasterizerBudgetCount([ Duration frameBuildBudget = kBuildBudget ]) => _extractGpuRasterizerDrawDurations()
      .where((Duration duration) => duration > kBuildBudget)
91 92 93
      .length;

  /// The total number of frames recorded in the timeline.
94
  int countFrames() => _extractFrameDurations().length;
95

96 97 98
  /// The total number of rasterizer cycles recorded in the timeline.
  int countRasterizations() => _extractGpuRasterizerDrawDurations().length;

99
  /// Encodes this summary as JSON.
100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149
  ///
  /// Data ends with "_time_millis" means time in milliseconds and numbers in
  /// the "frame_build_times", "frame_rasterizer_times", "frame_begin_times" and
  /// "frame_rasterizer_begin_times" lists are in microseconds.
  ///
  /// * "average_frame_build_time_millis": Average amount of time spent per
  ///   frame in the framework building widgets, updating layout, painting and
  ///   compositing.
  ///   See [computeAverageFrameBuildTimeMillis].
  /// * "90th_percentile_frame_build_time_millis" and
  ///   "99th_percentile_frame_build_time_millis": The p-th percentile frame
  ///   rasterization time in milliseconds. 90 and 99-th percentile number is
  ///   usually a better metric to estimate worse cases. See discussion in
  ///   https://github.com/flutter/flutter/pull/19121#issuecomment-419520765
  ///   See [computePercentileFrameBuildTimeMillis].
  /// * "worst_frame_build_time_millis": The longest frame build time.
  ///   See [computeWorstFrameBuildTimeMillis].
  /// * "missed_frame_build_budget_count': The number of frames that missed
  ///   the [kBuildBudget] and therefore are in the danger of missing frames.
  ///   See [computeMissedFrameBuildBudgetCount].
  /// * "average_frame_rasterizer_time_millis": Average amount of time spent
  ///   per frame in the engine rasterizer.
  ///   See [computeAverageFrameRasterizerTimeMillis].
  /// * "90th_percentile_frame_rasterizer_time_millis" and
  ///   "99th_percentile_frame_rasterizer_time_millis": The 90/99-th percentile
  ///   frame rasterization time in milliseconds.
  ///   See [computePercentileFrameRasterizerTimeMillis].
  /// * "worst_frame_rasterizer_time_millis": The longest frame rasterization
  ///   time.
  ///   See [computeWorstFrameRasterizerTimeMillis].
  /// * "missed_frame_rasterizer_budget_count": The number of frames that missed
  ///   the [kBuildBudget] on the raster thread and therefore are in the danger
  ///   of missing frames.
  ///   See [computeMissedFrameRasterizerBudgetCount].
  /// * "frame_count": The total number of frames recorded in the timeline. This
  ///   is also the length of the "frame_build_times" and the "frame_begin_times"
  ///   lists.
  ///   See [countFrames].
  /// * "frame_rasterizer_count": The total number of rasterizer cycles recorded
  ///   in the timeline. This is also the length of the "frame_rasterizer_times"
  ///   and the "frame_rasterizer_begin_times" lists.
  ///   See [countRasterizations].
  /// * "frame_build_times": The build time of each frame, by tracking the
  ///   [TimelineEvent] with name [kBuildFrameEventName].
  /// * "frame_rasterizer_times": The rasterize time of each frame, by tracking
  ///   the [TimelineEvent] with name [kRasterizeFrameEventName]
  /// * "frame_begin_times": The build begin timestamp of each frame.
  /// * "frame_rasterizer_begin_times": The rasterize begin time of each frame.
  /// * "average_vsync_transitions_missed": Computes the average of the
  ///   `vsync_transitions_missed` over the lag events.
150
  ///   See [SceneDisplayLagSummarizer.computeAverageVsyncTransitionsMissed].
151 152 153
  /// * "90th_percentile_vsync_transitions_missed" and
  ///   "99th_percentile_vsync_transitions_missed": The 90/99-th percentile
  ///   `vsync_transitions_missed` over the lag events.
154
  ///   See [SceneDisplayLagSummarizer.computePercentileVsyncTransitionsMissed].
155
  Map<String, dynamic> get summaryJson {
156
    final SceneDisplayLagSummarizer sceneDisplayLagSummarizer = _sceneDisplayLagSummarizer();
157
    final Map<String, dynamic> profilingSummary = _profilingSummarizer().summarize();
158

159
    final Map<String, dynamic> timelineSummary = <String, dynamic>{
160
      'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(),
161 162
      '90th_percentile_frame_build_time_millis': computePercentileFrameBuildTimeMillis(90.0),
      '99th_percentile_frame_build_time_millis': computePercentileFrameBuildTimeMillis(99.0),
163
      'worst_frame_build_time_millis': computeWorstFrameBuildTimeMillis(),
164
      'missed_frame_build_budget_count': computeMissedFrameBuildBudgetCount(),
165
      'average_frame_rasterizer_time_millis': computeAverageFrameRasterizerTimeMillis(),
166 167
      '90th_percentile_frame_rasterizer_time_millis': computePercentileFrameRasterizerTimeMillis(90.0),
      '99th_percentile_frame_rasterizer_time_millis': computePercentileFrameRasterizerTimeMillis(99.0),
168 169
      'worst_frame_rasterizer_time_millis': computeWorstFrameRasterizerTimeMillis(),
      'missed_frame_rasterizer_budget_count': computeMissedFrameRasterizerBudgetCount(),
170
      'frame_count': countFrames(),
171
      'frame_rasterizer_count': countRasterizations(),
172
      'frame_build_times': _extractFrameDurations()
173 174
          .map<int>((Duration duration) => duration.inMicroseconds)
          .toList(),
175
      'frame_rasterizer_times': _extractGpuRasterizerDrawDurations()
176 177 178 179 180 181 182 183
          .map<int>((Duration duration) => duration.inMicroseconds)
          .toList(),
      'frame_begin_times': _extractBeginTimestamps(kBuildFrameEventName)
          .map<int>((Duration duration) => duration.inMicroseconds)
          .toList(),
      'frame_rasterizer_begin_times': _extractBeginTimestamps(kRasterizeFrameEventName)
          .map<int>((Duration duration) => duration.inMicroseconds)
          .toList(),
184 185
      'average_vsync_transitions_missed': sceneDisplayLagSummarizer.computeAverageVsyncTransitionsMissed(),
      '90th_percentile_vsync_transitions_missed': sceneDisplayLagSummarizer.computePercentileVsyncTransitionsMissed(90.0),
186
      '99th_percentile_vsync_transitions_missed': sceneDisplayLagSummarizer.computePercentileVsyncTransitionsMissed(99.0),
187
    };
188 189 190

    timelineSummary.addAll(profilingSummary);
    return timelineSummary;
191 192 193
  }

  /// Writes all of the recorded timeline data to a file.
194 195 196 197
  ///
  /// See also:
  ///
  /// * [Timeline.fromJson], which explains detail about the timeline data.
198
  Future<void> writeTimelineToFile(
199 200
    String traceName, {
    String destinationDirectory,
201
    bool pretty = false,
202
  }) async {
203
    destinationDirectory ??= testOutputsDirectory;
204
    await fs.directory(destinationDirectory).create(recursive: true);
205
    final File file = fs.file(path.join(destinationDirectory, '$traceName.timeline.json'));
206
    await file.writeAsString(_encodeJson(_timeline.json, pretty));
207 208 209
  }

  /// Writes [summaryJson] to a file.
210
  Future<void> writeSummaryToFile(
211 212
    String traceName, {
    String destinationDirectory,
213
    bool pretty = false,
214
  }) async {
215
    destinationDirectory ??= testOutputsDirectory;
216
    await fs.directory(destinationDirectory).create(recursive: true);
217
    final File file = fs.file(path.join(destinationDirectory, '$traceName.timeline_summary.json'));
218 219 220
    await file.writeAsString(_encodeJson(summaryJson, pretty));
  }

221
  String _encodeJson(Map<String, dynamic> jsonObject, bool pretty) {
222
    return pretty
223 224
      ? _prettyEncoder.convert(jsonObject)
      : json.encode(jsonObject);
225 226
  }

227 228 229
  List<TimelineEvent> _extractNamedEvents(String name) {
    return _timeline.events
      .where((TimelineEvent event) => event.name == name)
230 231 232
      .toList();
  }

233
  List<TimelineEvent> _extractEventsWithNames(Set<String> names) {
234
    return _timeline.events
235
      .where((TimelineEvent event) => names.contains(event.name))
236 237 238
      .toList();
  }

239 240 241 242
  List<Duration> _extractDurations(
    String name,
    Duration extractor(TimelineEvent beginEvent, TimelineEvent endEvent),
  ) {
243
    final List<Duration> result = <Duration>[];
244
    final List<TimelineEvent> events = _extractNamedEvents(name);
245 246

    // Timeline does not guarantee that the first event is the "begin" event.
247 248 249 250 251 252 253 254 255 256
    TimelineEvent begin;
    for (final TimelineEvent event in events) {
      if (event.phase == 'B') {
        begin = event;
      } else {
        if (begin != null) {
          result.add(extractor(begin, event));
          // each begin only gets used once.
          begin = null;
        }
257 258 259 260 261 262
      }
    }

    return result;
  }

263 264
  /// Extracts Duration list that are reported as a pair of begin/end events.
  ///
265 266 267 268 269 270
  /// Extracts Duration of events by looking for events with the name and phase
  /// begin ("ph": "B"). This routine assumes that the next event with the same
  /// name is phase end ("ph": "E"), but it's not examined.
  /// "SceneDisplayLag" event is an exception, with phase ("ph") labeled
  /// 'b' and 'e', meaning begin and end phase for an async event.
  /// See [SceneDisplayLagSummarizer].
271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295
  /// See: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU
  List<Duration> _extractBeginEndEvents(String name) {
    return _extractDurations(
      name,
      (TimelineEvent beginEvent, TimelineEvent endEvent) {
        return Duration(microseconds: endEvent.timestampMicros - beginEvent.timestampMicros);
      },
    );
  }

  List<Duration> _extractBeginTimestamps(String name) {
    final List<Duration> result = _extractDurations(
      name,
      (TimelineEvent beginEvent, TimelineEvent endEvent) {
        return Duration(microseconds: beginEvent.timestampMicros);
      },
    );

    // Align timestamps so the first event is at 0.
    for (int i = result.length - 1; i >= 0; i -= 1) {
      result[i] = result[i] - result[0];
    }
    return result;
  }

296 297
  double _averageInMillis(Iterable<Duration> durations) {
    if (durations.isEmpty)
298
      throw ArgumentError('durations is empty!');
299
    final double total = durations.fold<double>(0.0, (double t, Duration duration) => t + duration.inMicroseconds.toDouble() / 1000.0);
300
    return total / durations.length;
301 302
  }

303 304
  double _percentileInMillis(Iterable<Duration> durations, double percentile) {
    if (durations.isEmpty)
305
      throw ArgumentError('durations is empty!');
306
    assert(percentile >= 0.0 && percentile <= 100.0);
307
    final List<double> doubles = durations.map<double>((Duration duration) => duration.inMicroseconds.toDouble() / 1000.0).toList();
308
    return findPercentile(doubles, percentile);
309 310
  }

311 312
  double _maxInMillis(Iterable<Duration> durations) {
    if (durations.isEmpty)
313
      throw ArgumentError('durations is empty!');
314
    return durations
315
        .map<double>((Duration duration) => duration.inMicroseconds.toDouble() / 1000.0)
316
        .reduce(math.max);
317 318
  }

319 320
  SceneDisplayLagSummarizer _sceneDisplayLagSummarizer() => SceneDisplayLagSummarizer(_extractNamedEvents(kSceneDisplayLagEvent));

321
  List<Duration> _extractGpuRasterizerDrawDurations() => _extractBeginEndEvents(kRasterizeFrameEventName);
322

323
  ProfilingSummarizer _profilingSummarizer() => ProfilingSummarizer.fromEvents(_extractEventsWithNames(kProfilingEvents));
324

325
  List<Duration> _extractFrameDurations() => _extractBeginEndEvents(kBuildFrameEventName);
326
}