[flutter_driver] Add SceneDisplayLag stats to timeline summary (#54218)

dev/devicelab/lib/tasks/perf_tests.dart

@@ -189,7 +189,6 @@ TaskFunction createColorFilterAndFadePerfTest() {
   ).run;
 }
 
-
 /// Measure application startup performance.
 class StartupTest {
   const StartupTest(this.testDirectory, { this.reportMetrics = true });
@@ -281,6 +280,9 @@ class PerfTest {
         'worst_frame_rasterizer_time_millis',
         '90th_percentile_frame_rasterizer_time_millis',
         '99th_percentile_frame_rasterizer_time_millis',
+        'average_vsync_transitions_missed',
+        '90th_percentile_vsync_transitions_missed',
+        '99th_percentile_vsync_transitions_missed',
         if (needsMeasureCpuGPu) 'cpu_percentage',
         if (needsMeasureCpuGPu) 'gpu_percentage',
       ]);

packages/flutter_driver/lib/src/driver/scene_display_lag_summarizer.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 'timeline.dart';
+
+/// Key for SceneDisplayLag timeline events.
+const String kSceneDisplayLagEvent = 'SceneDisplayLag';
+
+const String _kVsyncTransitionsMissed = 'vsync_transitions_missed';
+
+/// Returns the [p]-th percentile element from the [doubles].
+///
+/// Note: [doubles] will be sorted.
+double findPercentile(List<double> doubles, double p) {
+  assert(doubles.isNotEmpty);
+  doubles.sort();
+  return doubles[((doubles.length - 1) * (p / 100)).round()];
+}
+
+/// Summarizes [TimelineEvents]s corresponding to [kSceneDisplayLagEvent] events.
+///
+/// A sample event (some fields have been omitted for brewity):
+/// ```
+///     {
+///      "name": "SceneDisplayLag",
+///      "ts": 408920509340,
+///      "ph": "b", (this can be 'b' or 'e' for begin or end)
+///      "args": {
+///        "frame_target_time": "408920509340458",
+///        "current_frame_target_time": "408920542689291",
+///        "vsync_transitions_missed": "2"
+///      }
+///    },
+/// ```
+///
+/// `vsync_transitions_missed` corresponds to the elapsed number of frame budget
+/// durations between when the frame was scheduled to be displayed, i.e, the
+/// `frame_target_time` and the next vsync pulse timestamp, i.e, the
+/// `current_frame_target_time`.
+class SceneDisplayLagSummarizer {
+  /// Creates a SceneDisplayLagSummarizer given the timeline events.
+  SceneDisplayLagSummarizer(this.sceneDisplayLagEvents) {
+    for (final TimelineEvent event in sceneDisplayLagEvents) {
+      assert(event.name == kSceneDisplayLagEvent);
+    }
+  }
+
+  /// The scene display lag events.
+  final List<TimelineEvent> sceneDisplayLagEvents;
+
+  /// Computes the average of the `vsync_transitions_missed` over the lag events.
+  double computeAverageVsyncTransitionsMissed() {
+    if (sceneDisplayLagEvents.isEmpty) {
+      return 0;
+    }
+
+    final double total = sceneDisplayLagEvents
+        .map(_getVsyncTransitionsMissed)
+        .reduce((double a, double b) => a + b);
+    return total / sceneDisplayLagEvents.length;
+  }
+
+  /// The [percentile]-th percentile `vsync_transitions_missed` over the lag events.
+  double computePercentileVsyncTransitionsMissed(double percentile) {
+    if (sceneDisplayLagEvents.isEmpty) {
+      return 0;
+    }
+
+    final List<double> doubles =
+        sceneDisplayLagEvents.map(_getVsyncTransitionsMissed).toList();
+    return findPercentile(doubles, percentile);
+  }
+
+  double _getVsyncTransitionsMissed(TimelineEvent e) {
+    assert(e.name == kSceneDisplayLagEvent);
+    assert(e.arguments.containsKey(_kVsyncTransitionsMissed));
+    return (e.arguments[_kVsyncTransitionsMissed] as num).toDouble();
+  }
+}

packages/flutter_driver/lib/src/driver/timeline_summary.dart

@@ -10,6 +10,7 @@ import 'package:file/file.dart';
 import 'package:path/path.dart' as path;
 
 import 'common.dart';
+import 'scene_display_lag_summarizer.dart';
 import 'timeline.dart';
 
 const JsonEncoder _prettyEncoder = JsonEncoder.withIndent('  ');
@@ -85,6 +86,8 @@ class TimelineSummary {
 
   /// Encodes this summary as JSON.
   Map<String, dynamic> get summaryJson {
+    final SceneDisplayLagSummarizer sceneDisplayLagSummarizer = _sceneDisplayLagSummarizer();
+
     return <String, dynamic>{
       'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(),
       '90th_percentile_frame_build_time_millis': computePercentileFrameBuildTimeMillis(90.0),
@@ -105,7 +108,10 @@ class TimelineSummary {
         .toList(),
       'frame_begin_times': _extractBeginTimestamps('Frame')
         .map<int>((Duration duration) => duration.inMicroseconds)
-        .toList()
+        .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)
     };
   }
 
@@ -208,9 +214,7 @@ class TimelineSummary {
       throw ArgumentError('durations is empty!');
     assert(percentile >= 0.0 && percentile <= 100.0);
     final List<double> doubles = durations.map<double>((Duration duration) => duration.inMicroseconds.toDouble() / 1000.0).toList();
-    doubles.sort();
-    return doubles[((doubles.length - 1) * (percentile / 100)).round()];
-
+    return findPercentile(doubles, percentile);
   }
 
   double _maxInMillis(Iterable<Duration> durations) {
@@ -221,6 +225,8 @@ class TimelineSummary {
         .reduce(math.max);
   }
 
+  SceneDisplayLagSummarizer _sceneDisplayLagSummarizer() => SceneDisplayLagSummarizer(_extractNamedEvents(kSceneDisplayLagEvent));
+
   List<Duration> _extractGpuRasterizerDrawDurations() => _extractBeginEndEvents('GPURasterizer::Draw');
 
   List<Duration> _extractFrameDurations() => _extractBeginEndEvents('Frame');

packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart

@@ -7,6 +7,7 @@ import 'dart:convert' show json;
 import 'package:file/file.dart';
 import 'package:flutter_driver/flutter_driver.dart';
 import 'package:flutter_driver/src/driver/common.dart';
+import 'package:flutter_driver/src/driver/scene_display_lag_summarizer.dart';
 import 'package:path/path.dart' as path;
 
 import '../../common.dart';
@@ -44,6 +45,24 @@ void main() {
       'ts': timeStamp,
     };
 
+    Map<String, dynamic> lagBegin(int timeStamp, int vsyncsMissed) => <String, dynamic>{
+      'name': 'SceneDisplayLag',
+      'ph': 'b',
+      'ts': timeStamp,
+      'args': <String, int>{
+        'vsync_transitions_missed': vsyncsMissed
+      }
+    };
+
+    Map<String, dynamic> lagEnd(int timeStamp, int vsyncsMissed) => <String, dynamic>{
+      'name': 'SceneDisplayLag',
+      'ph': 'e',
+      'ts': timeStamp,
+      'args': <String, int>{
+        'vsync_transitions_missed': vsyncsMissed
+      }
+    };
+
     List<Map<String, dynamic>> rasterizeTimeSequenceInMillis(List<int> sequence) {
       final List<Map<String, dynamic>> result = <Map<String, dynamic>>[];
       int t = 0;
@@ -356,6 +375,9 @@ void main() {
             'frame_build_times': <int>[17000, 9000, 19000],
             'frame_rasterizer_times': <int>[18000, 10000, 20000],
             'frame_begin_times': <int>[0, 18000, 28000],
+            'average_vsync_transitions_missed': 0.0,
+            '90th_percentile_vsync_transitions_missed': 0.0,
+            '99th_percentile_vsync_transitions_missed': 0.0
           },
         );
       });
@@ -391,6 +413,9 @@ void main() {
           frameBegin(1000), frameEnd(18000),
           frameBegin(19000), frameEnd(28000),
           frameBegin(29000), frameEnd(48000),
+          lagBegin(1000, 4), lagEnd(2000, 4),
+          lagBegin(1200, 12), lagEnd(2400, 12),
+          lagBegin(4200, 8), lagEnd(9400, 8),
         ]).writeSummaryToFile('test', destinationDirectory: tempDir.path);
         final String written =
             await fs.file(path.join(tempDir.path, 'test.timeline_summary.json')).readAsString();
@@ -409,8 +434,62 @@ void main() {
           'frame_build_times': <int>[17000, 9000, 19000],
           'frame_rasterizer_times': <int>[18000, 10000, 20000],
           'frame_begin_times': <int>[0, 18000, 28000],
+          'average_vsync_transitions_missed': 8.0,
+          '90th_percentile_vsync_transitions_missed': 12.0,
+          '99th_percentile_vsync_transitions_missed': 12.0
         });
       });
     });
+
+    group('SceneDisplayLagSummarizer tests', () {
+      SceneDisplayLagSummarizer summarize(List<Map<String, dynamic>> traceEvents) {
+          final Timeline timeline = Timeline.fromJson(<String, dynamic>{
+          'traceEvents': traceEvents,
+          });
+          return SceneDisplayLagSummarizer(timeline.events);
+      }
+
+      test('average_vsyncs_missed', () async {
+        final SceneDisplayLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          lagBegin(1000, 4), lagEnd(2000, 4),
+          lagBegin(1200, 12), lagEnd(2400, 12),
+          lagBegin(4200, 8), lagEnd(9400, 8),
+        ]);
+        expect(summarizer.computeAverageVsyncTransitionsMissed(), 8.0);
+      });
+
+      test('all stats are 0 for 0 missed transitions', () async {
+        final SceneDisplayLagSummarizer summarizer = summarize(<Map<String, dynamic>>[]);
+        expect(summarizer.computeAverageVsyncTransitionsMissed(), 0.0);
+        expect(summarizer.computePercentileVsyncTransitionsMissed(90.0), 0.0);
+        expect(summarizer.computePercentileVsyncTransitionsMissed(99.0), 0.0);
+      });
+
+      test('90th_percentile_vsyncs_missed', () async {
+        final SceneDisplayLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          lagBegin(1000, 4), lagEnd(2000, 4),
+          lagBegin(1200, 12), lagEnd(2400, 12),
+          lagBegin(4200, 8), lagEnd(9400, 8),
+          lagBegin(6100, 14), lagEnd(11000, 14),
+          lagBegin(7100, 16), lagEnd(11500, 16),
+          lagBegin(7400, 11), lagEnd(13000, 11),
+          lagBegin(8200, 27), lagEnd(14100, 27),
+          lagBegin(8700, 7), lagEnd(14300, 7),
+          lagBegin(24200, 4187), lagEnd(39400, 4187),
+        ]);
+        expect(summarizer.computePercentileVsyncTransitionsMissed(90), 27.0);
+      });
+
+      test('99th_percentile_vsyncs_missed', () async {
+        final SceneDisplayLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          lagBegin(1000, 4), lagEnd(2000, 4),
+          lagBegin(1200, 12), lagEnd(2400, 12),
+          lagBegin(4200, 8), lagEnd(9400, 8),
+          lagBegin(6100, 14), lagEnd(11000, 14),
+          lagBegin(24200, 4187), lagEnd(39400, 4187),
+        ]);
+        expect(summarizer.computePercentileVsyncTransitionsMissed(99), 4187.0);
+      });
+    });
   });
 }