timeline_summary.dart

// Copyright 2014 The Flutter Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

import 'dart:convert' show JsonEncoder, json;
import 'dart:math' as math;

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

import 'common.dart';
import 'gc_summarizer.dart';
import 'percentile_utils.dart';
import 'profiling_summarizer.dart';
import 'raster_cache_summarizer.dart';
import 'refresh_rate_summarizer.dart';
import 'scene_display_lag_summarizer.dart';
import 'timeline.dart';
import 'vsync_frame_lag_summarizer.dart';

const JsonEncoder _prettyEncoder = JsonEncoder.withIndent('  ');

const String _kEmptyDurationMessage = r'''
The TimelineSummary had no events to summarize.

This can happen if the timeline summarization covered too short of a period
or if the driver script failed to interact with the application to generate
events. For example, if your driver script contained only a "driver.scroll()"
command but the app under test was not scrollable then no events would be
generated by the interaction.
''';

/// 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.
const Duration kBuildBudget = Duration(milliseconds: 16);

/// 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';

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

  final Timeline _timeline;

  /// Average amount of time spent per frame in the framework building widgets,
  /// updating layout, painting and compositing.
  ///
  /// Throws a [StateError] if this summary contains no timeline events.
  double computeAverageFrameBuildTimeMillis() {
    return _averageInMillis(_extractFrameDurations());
  }

  /// The [p]-th percentile frame rasterization time in milliseconds.
  ///
  /// Throws a [StateError] if this summary contains no timeline events.
  double computePercentileFrameBuildTimeMillis(double p) {
    return _percentileInMillis(_extractFrameDurations(), p);
  }

  /// The longest frame build time in milliseconds.
  ///
  /// Throws a [StateError] if this summary contains no timeline events.
  double computeWorstFrameBuildTimeMillis() {
    return _maxInMillis(_extractFrameDurations());
  }

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

  /// Average amount of time spent per frame in the engine rasterizer.
  ///
  /// Throws a [StateError] if this summary contains no timeline events.
  double computeAverageFrameRasterizerTimeMillis() {
    return _averageInMillis(_extractGpuRasterizerDrawDurations());
  }

  /// The longest frame rasterization time in milliseconds.
  ///
  /// Throws a [StateError] if this summary contains no timeline events.
  double computeWorstFrameRasterizerTimeMillis() {
    return _maxInMillis(_extractGpuRasterizerDrawDurations());
  }

  /// The [p]-th percentile frame rasterization time in milliseconds.
  ///
  /// Throws a [StateError] if this summary contains no timeline events.
  double computePercentileFrameRasterizerTimeMillis(double p) {
    return _percentileInMillis(_extractGpuRasterizerDrawDurations(), p);
  }

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

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

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

  /// The total number of old generation garbage collections recorded in the timeline.
  int oldGenerationGarbageCollections() {
    return _timeline.events!.where((TimelineEvent event) {
      return event.category == 'GC' && event.name == 'CollectOldGeneration';
    }).length;
  }

  /// The total number of new generation garbage collections recorded in the timeline.
  int newGenerationGarbageCollections() {
    return _timeline.events!.where((TimelineEvent event) {
      return event.category == 'GC' && event.name == 'CollectNewGeneration';
    }).length;
  }

  /// Encodes this summary as JSON.
  ///
  /// 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.
  ///   See [SceneDisplayLagSummarizer.computeAverageVsyncTransitionsMissed].
  /// * "90th_percentile_vsync_transitions_missed" and
  ///   "99th_percentile_vsync_transitions_missed": The 90/99-th percentile
  ///   `vsync_transitions_missed` over the lag events.
  ///   See [SceneDisplayLagSummarizer.computePercentileVsyncTransitionsMissed].
  /// * "average_vsync_frame_lag": Computes the average of the time between
  ///   platform vsync signal and the engine frame process start time.
  ///   See [VsyncFrameLagSummarizer.computeAverageVsyncFrameLag].
  /// * "90th_percentile_vsync_frame_lag" and "99th_percentile_vsync_frame_lag":
  ///   The 90/99-th percentile delay between platform vsync signal and engine
  ///   frame process start time.
  ///   See [VsyncFrameLagSummarizer.computePercentileVsyncFrameLag].
  /// * "average_layer_cache_count": The average of the values seen for the
  ///   count of the engine layer cache entries.
  ///   See [RasterCacheSummarizer.computeAverageLayerCount].
  /// * "90th_percentile_layer_cache_count" and
  ///   "99th_percentile_layer_cache_count": The 90/99-th percentile values seen
  ///   for the count of the engine layer cache entries.
  ///   See [RasterCacheSummarizer.computePercentileLayerCount].
  /// * "worst_layer_cache_count": The worst (highest) value seen for the
  ///   count of the engine layer cache entries.
  ///   See [RasterCacheSummarizer.computeWorstLayerCount].
  /// * "average_layer_cache_memory": The average of the values seen for the
  ///   memory used for the engine layer cache entries, in megabytes.
  ///   See [RasterCacheSummarizer.computeAverageLayerMemory].
  /// * "90th_percentile_layer_cache_memory" and
  ///   "99th_percentile_layer_cache_memory": The 90/99-th percentile values seen
  ///   for the memory used for the engine layer cache entries.
  ///   See [RasterCacheSummarizer.computePercentileLayerMemory].
  /// * "worst_layer_cache_memory": The worst (highest) value seen for the
  ///   memory used for the engine layer cache entries.
  ///   See [RasterCacheSummarizer.computeWorstLayerMemory].
  /// * "average_picture_cache_count": The average of the values seen for the
  ///   count of the engine picture cache entries.
  ///   See [RasterCacheSummarizer.computeAveragePictureCount].
  /// * "90th_percentile_picture_cache_count" and
  ///   "99th_percentile_picture_cache_count": The 90/99-th percentile values seen
  ///   for the count of the engine picture cache entries.
  ///   See [RasterCacheSummarizer.computePercentilePictureCount].
  /// * "worst_picture_cache_count": The worst (highest) value seen for the
  ///   count of the engine picture cache entries.
  ///   See [RasterCacheSummarizer.computeWorstPictureCount].
  /// * "average_picture_cache_memory": The average of the values seen for the
  ///   memory used for the engine picture cache entries, in megabytes.
  ///   See [RasterCacheSummarizer.computeAveragePictureMemory].
  /// * "90th_percentile_picture_cache_memory" and
  ///   "99th_percentile_picture_cache_memory": The 90/99-th percentile values seen
  ///   for the memory used for the engine picture cache entries.
  ///   See [RasterCacheSummarizer.computePercentilePictureMemory].
  /// * "worst_picture_cache_memory": The worst (highest) value seen for the
  ///   memory used for the engine picture cache entries.
  ///   See [RasterCacheSummarizer.computeWorstPictureMemory].
  Map<String, dynamic> get summaryJson {
    final SceneDisplayLagSummarizer sceneDisplayLagSummarizer = _sceneDisplayLagSummarizer();
    final VsyncFrameLagSummarizer vsyncFrameLagSummarizer = _vsyncFrameLagSummarizer();
    final Map<String, dynamic> profilingSummary = _profilingSummarizer().summarize();
    final RasterCacheSummarizer rasterCacheSummarizer = _rasterCacheSummarizer();
    final GCSummarizer gcSummarizer = _gcSummarizer();
    final RefreshRateSummary refreshRateSummary = RefreshRateSummary(vsyncEvents: _extractNamedEvents(kUIThreadVsyncProcessEvent));

    final Map<String, dynamic> timelineSummary = <String, dynamic>{
      'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(),
      '90th_percentile_frame_build_time_millis': computePercentileFrameBuildTimeMillis(90.0),
      '99th_percentile_frame_build_time_millis': computePercentileFrameBuildTimeMillis(99.0),
      'worst_frame_build_time_millis': computeWorstFrameBuildTimeMillis(),
      'missed_frame_build_budget_count': computeMissedFrameBuildBudgetCount(),
      'average_frame_rasterizer_time_millis': computeAverageFrameRasterizerTimeMillis(),
      '90th_percentile_frame_rasterizer_time_millis': computePercentileFrameRasterizerTimeMillis(90.0),
      '99th_percentile_frame_rasterizer_time_millis': computePercentileFrameRasterizerTimeMillis(99.0),
      'worst_frame_rasterizer_time_millis': computeWorstFrameRasterizerTimeMillis(),
      'missed_frame_rasterizer_budget_count': computeMissedFrameRasterizerBudgetCount(),
      'frame_count': countFrames(),
      'frame_rasterizer_count': countRasterizations(),
      'new_gen_gc_count': newGenerationGarbageCollections(),
      'old_gen_gc_count': oldGenerationGarbageCollections(),
      'frame_build_times': _extractFrameDurations()
          .map<int>((Duration duration) => duration.inMicroseconds)
          .toList(),
      'frame_rasterizer_times': _extractGpuRasterizerDrawDurations()
          .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(),
      'average_vsync_transitions_missed': sceneDisplayLagSummarizer.computeAverageVsyncTransitionsMissed(),
      '90th_percentile_vsync_transitions_missed': sceneDisplayLagSummarizer.computePercentileVsyncTransitionsMissed(90.0),
      '99th_percentile_vsync_transitions_missed': sceneDisplayLagSummarizer.computePercentileVsyncTransitionsMissed(99.0),
      'average_vsync_frame_lag': vsyncFrameLagSummarizer.computeAverageVsyncFrameLag(),
      '90th_percentile_vsync_frame_lag': vsyncFrameLagSummarizer.computePercentileVsyncFrameLag(90.0),
      '99th_percentile_vsync_frame_lag': vsyncFrameLagSummarizer.computePercentileVsyncFrameLag(99.0),
      'average_layer_cache_count': rasterCacheSummarizer.computeAverageLayerCount(),
      '90th_percentile_layer_cache_count': rasterCacheSummarizer.computePercentileLayerCount(90.0),
      '99th_percentile_layer_cache_count': rasterCacheSummarizer.computePercentileLayerCount(99.0),
      'worst_layer_cache_count': rasterCacheSummarizer.computeWorstLayerCount(),
      'average_layer_cache_memory': rasterCacheSummarizer.computeAverageLayerMemory(),
      '90th_percentile_layer_cache_memory': rasterCacheSummarizer.computePercentileLayerMemory(90.0),
      '99th_percentile_layer_cache_memory': rasterCacheSummarizer.computePercentileLayerMemory(99.0),
      'worst_layer_cache_memory': rasterCacheSummarizer.computeWorstLayerMemory(),
      'average_picture_cache_count': rasterCacheSummarizer.computeAveragePictureCount(),
      '90th_percentile_picture_cache_count': rasterCacheSummarizer.computePercentilePictureCount(90.0),
      '99th_percentile_picture_cache_count': rasterCacheSummarizer.computePercentilePictureCount(99.0),
      'worst_picture_cache_count': rasterCacheSummarizer.computeWorstPictureCount(),
      'average_picture_cache_memory': rasterCacheSummarizer.computeAveragePictureMemory(),
      '90th_percentile_picture_cache_memory': rasterCacheSummarizer.computePercentilePictureMemory(90.0),
      '99th_percentile_picture_cache_memory': rasterCacheSummarizer.computePercentilePictureMemory(99.0),
      'worst_picture_cache_memory': rasterCacheSummarizer.computeWorstPictureMemory(),
      'total_ui_gc_time': gcSummarizer.totalGCTimeMillis,
      '30hz_frame_percentage': refreshRateSummary.percentageOf30HzFrames,
      '60hz_frame_percentage': refreshRateSummary.percentageOf60HzFrames,
      '80hz_frame_percentage': refreshRateSummary.percentageOf80HzFrames,
      '90hz_frame_percentage': refreshRateSummary.percentageOf90HzFrames,
      '120hz_frame_percentage': refreshRateSummary.percentageOf120HzFrames,
      'illegal_refresh_rate_frame_count': refreshRateSummary.framesWithIllegalRefreshRate.length,
    };

    timelineSummary.addAll(profilingSummary);
    return timelineSummary;
  }

  /// Writes all of the recorded timeline data to a file.
  ///
  /// By default, this will dump [summaryJson] to a companion file named
  /// `$traceName.timeline_summary.json`. If you want to skip the summary, set
  /// the `includeSummary` parameter to false.
  ///
  /// See also:
  ///
  /// * [Timeline.fromJson], which explains detail about the timeline data.
  Future<void> writeTimelineToFile(
    String traceName, {
    String? destinationDirectory,
    bool pretty = false,
    bool includeSummary = true,
  }) async {
    destinationDirectory ??= testOutputsDirectory;
    await fs.directory(destinationDirectory).create(recursive: true);
    final File file = fs.file(path.join(destinationDirectory, '$traceName.timeline.json'));
    await file.writeAsString(_encodeJson(_timeline.json, pretty));

    if (includeSummary) {
      await _writeSummaryToFile(traceName, destinationDirectory: destinationDirectory, pretty: pretty);
    }
  }

  /// Writes [summaryJson] to a file.
  @Deprecated(
    'Use TimelineSummary.writeTimelineToFile. '
    'This feature was deprecated after v2.1.0-13.0.pre.'
  )
  Future<void> writeSummaryToFile(
    String traceName, {
    String? destinationDirectory,
    bool pretty = false,
  }) async {
    destinationDirectory ??= testOutputsDirectory;
    await _writeSummaryToFile(traceName, destinationDirectory: destinationDirectory, pretty: pretty);
  }

  Future<void> _writeSummaryToFile(
    String traceName, {
    required String destinationDirectory,
    bool pretty = false,
  }) async {
    await fs.directory(destinationDirectory).create(recursive: true);
    final File file = fs.file(path.join(destinationDirectory, '$traceName.timeline_summary.json'));
    await file.writeAsString(_encodeJson(summaryJson, pretty));
  }

  String _encodeJson(Map<String, dynamic> jsonObject, bool pretty) {
    return pretty
      ? _prettyEncoder.convert(jsonObject)
      : json.encode(jsonObject);
  }

  List<TimelineEvent> _extractNamedEvents(String name) {
    return _timeline.events!
      .where((TimelineEvent event) => event.name == name)
      .toList();
  }

  List<TimelineEvent> _extractEventsWithNames(Set<String> names) {
    return _timeline.events!
      .where((TimelineEvent event) => names.contains(event.name))
      .toList();
  }

  List<Duration> _extractDurations(
    String name,
    Duration Function(TimelineEvent beginEvent, TimelineEvent endEvent) extractor,
  ) {
    final List<Duration> result = <Duration>[];
    final List<TimelineEvent> events = _extractNamedEvents(name);

    // Timeline does not guarantee that the first event is the "begin" event.
    TimelineEvent? begin;
    for (final TimelineEvent event in events) {
      if (event.phase == 'B' || event.phase == 'b') {
        begin = event;
      } else {
        if (begin != null) {
          result.add(extractor(begin, event));
          // each begin only gets used once.
          begin = null;
        }
      }
    }

    return result;
  }

  /// Extracts Duration list that are reported as a pair of begin/end events.
  ///
  /// 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].
  /// 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;
  }

  double _averageInMillis(List<Duration> durations) {
    if (durations.isEmpty) {
      throw StateError(_kEmptyDurationMessage);
    }
    final double total = durations.fold<double>(0.0, (double t, Duration duration) => t + duration.inMicroseconds.toDouble() / 1000.0);
    return total / durations.length;
  }

  double _percentileInMillis(List<Duration> durations, double percentile) {
    if (durations.isEmpty) {
      throw StateError(_kEmptyDurationMessage);
    }
    assert(percentile >= 0.0 && percentile <= 100.0);
    final List<double> doubles = durations.map<double>((Duration duration) => duration.inMicroseconds.toDouble() / 1000.0).toList();
    return findPercentile(doubles, percentile);
  }

  double _maxInMillis(List<Duration> durations) {
    if (durations.isEmpty) {
      throw StateError(_kEmptyDurationMessage);
    }
    return durations
        .map<double>((Duration duration) => duration.inMicroseconds.toDouble() / 1000.0)
        .reduce(math.max);
  }

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

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

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

  List<Duration> _extractFrameDurations() => _extractBeginEndEvents(kBuildFrameEventName);

  VsyncFrameLagSummarizer _vsyncFrameLagSummarizer() => VsyncFrameLagSummarizer(_extractEventsWithNames(kVsyncTimelineEventNames));

  RasterCacheSummarizer _rasterCacheSummarizer() => RasterCacheSummarizer(_extractNamedEvents(kRasterCacheEvent));

  GCSummarizer _gcSummarizer() => GCSummarizer.fromEvents(_extractEventsWithNames(kGCRootEvents));
}