Add timeline summary entries to capture vsync frame lag (#79090)

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

@@ -13,6 +13,7 @@ import 'percentile_utils.dart';
 import 'profiling_summarizer.dart';
 import 'scene_display_lag_summarizer.dart';
 import 'timeline.dart';
+import 'vsync_frame_lag_summarizer.dart';
 
 const JsonEncoder _prettyEncoder = JsonEncoder.withIndent('  ');
 
@@ -150,8 +151,16 @@ class TimelineSummary {
   ///   "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].
   Map<String, dynamic> get summaryJson {
     final SceneDisplayLagSummarizer sceneDisplayLagSummarizer = _sceneDisplayLagSummarizer();
+    final VsyncFrameLagSummarizer vsyncFrameLagSummarizer = _vsyncFrameLagSummarizer();
     final Map<String, dynamic> profilingSummary = _profilingSummarizer().summarize();
 
     final Map<String, dynamic> timelineSummary = <String, dynamic>{
@@ -182,6 +191,9 @@ class TimelineSummary {
       '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),
     };
 
     timelineSummary.addAll(profilingSummary);
@@ -321,4 +333,6 @@ class TimelineSummary {
   ProfilingSummarizer _profilingSummarizer() => ProfilingSummarizer.fromEvents(_extractEventsWithNames(kProfilingEvents));
 
   List<Duration> _extractFrameDurations() => _extractBeginEndEvents(kBuildFrameEventName);
+
+  VsyncFrameLagSummarizer _vsyncFrameLagSummarizer() => VsyncFrameLagSummarizer(_extractEventsWithNames(kVsyncTimelineEventNames));
 }

packages/flutter_driver/lib/src/driver/vsync_frame_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 'percentile_utils.dart';
+import 'timeline.dart';
+
+const String _kPlatformVsyncEvent = 'VSYNC';
+const String _kUIThreadVsyncProcessEvent = 'VsyncProcessCallback';
+
+/// Event names for frame lag related timeline events.
+const Set<String> kVsyncTimelineEventNames = <String>{
+  _kUIThreadVsyncProcessEvent,
+  _kPlatformVsyncEvent,
+};
+
+/// Summarizes [TimelineEvents]s corresponding to [kVsyncTimelineEventNames] events.
+///
+/// `VsyncFrameLag` is the time between when a platform vsync event is received to
+/// when the frame starts getting processed by the Flutter Engine. This delay is
+/// typically seen due to non-frame workload related dart tasks being scheduled
+/// on the UI thread.
+class VsyncFrameLagSummarizer {
+  /// Creates a VsyncFrameLagSummarizer given the timeline events.
+  VsyncFrameLagSummarizer(this.vsyncEvents);
+
+  /// Timeline events with names in [kVsyncTimelineEventNames].
+  final List<TimelineEvent> vsyncEvents;
+
+  /// Computes the average `VsyncFrameLag` over the period of the timeline.
+  double computeAverageVsyncFrameLag() {
+    final List<double> vsyncFrameLags =
+        _computePlatformToFlutterVsyncBeginLags();
+    if (vsyncFrameLags.isEmpty) {
+      return 0;
+    }
+
+    final double total = vsyncFrameLags.reduce((double a, double b) => a + b);
+    return total / vsyncFrameLags.length;
+  }
+
+  /// Computes the [percentile]-th percentile `VsyncFrameLag` over the
+  /// period of the timeline.
+  double computePercentileVsyncFrameLag(double percentile) {
+    final List<double> vsyncFrameLags =
+        _computePlatformToFlutterVsyncBeginLags();
+    if (vsyncFrameLags.isEmpty) {
+      return 0;
+    }
+    return findPercentile(vsyncFrameLags, percentile);
+  }
+
+  List<double> _computePlatformToFlutterVsyncBeginLags() {
+    int platformIdx = -1;
+    final List<double> result = <double>[];
+    for (int i = 0; i < vsyncEvents.length; i++) {
+      final TimelineEvent event = vsyncEvents[i];
+      if (event.phase != 'B') {
+        continue;
+      }
+      if (event.name == _kPlatformVsyncEvent) {
+        // There was a vsync that resulted in a frame not being built.
+        // This needs to be penalized.
+        if (platformIdx != -1) {
+          final int prevTS = vsyncEvents[platformIdx].timestampMicros!;
+          result.add((event.timestampMicros! - prevTS).toDouble());
+        }
+        platformIdx = i;
+      } else if (platformIdx != -1) {
+        final int platformTS = vsyncEvents[platformIdx].timestampMicros!;
+        result.add((event.timestampMicros! - platformTS).toDouble());
+        platformIdx = -1;
+      }
+    }
+    return result;
+  }
+}

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

@@ -8,6 +8,7 @@ import 'package:file/file.dart';
 import 'package:flutter_driver/flutter_driver.dart';
 import 'package:flutter_driver/src/driver/profiling_summarizer.dart';
 import 'package:flutter_driver/src/driver/scene_display_lag_summarizer.dart';
+import 'package:flutter_driver/src/driver/vsync_frame_lag_summarizer.dart';
 import 'package:path/path.dart' as path;
 
 import '../../common.dart';
@@ -82,6 +83,18 @@ void main() {
       }
     };
 
+    Map<String, dynamic> platformVsync(int timeStamp) => <String, dynamic>{
+      'name': 'VSYNC',
+      'ph': 'B',
+      'ts': timeStamp,
+    };
+
+    Map<String, dynamic> vsyncCallback(int timeStamp) => <String, dynamic>{
+      'name': 'VsyncProcessCallback',
+      'ph': 'B',
+      'ts': timeStamp,
+    };
+
     List<Map<String, dynamic>> rasterizeTimeSequenceInMillis(List<int> sequence) {
       final List<Map<String, dynamic>> result = <Map<String, dynamic>>[];
       int t = 0;
@@ -398,7 +411,10 @@ void main() {
             'frame_rasterizer_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
+            '99th_percentile_vsync_transitions_missed': 0.0,
+            'average_vsync_frame_lag': 0.0,
+            '90th_percentile_vsync_frame_lag': 0.0,
+            '99th_percentile_vsync_frame_lag': 0.0,
           },
         );
       });
@@ -439,6 +455,7 @@ void main() {
           lagBegin(4200, 8), lagEnd(9400, 8),
           cpuUsage(5000, 20), cpuUsage(5010, 60),
           memoryUsage(6000, 20, 40), memoryUsage(6100, 30, 45),
+          platformVsync(7000), vsyncCallback(7500),
         ]).writeSummaryToFile('test', destinationDirectory: tempDir.path);
         final String written =
             await fs.file(path.join(tempDir.path, 'test.timeline_summary.json')).readAsString();
@@ -462,6 +479,9 @@ void main() {
           'average_vsync_transitions_missed': 8.0,
           '90th_percentile_vsync_transitions_missed': 12.0,
           '99th_percentile_vsync_transitions_missed': 12.0,
+          'average_vsync_frame_lag': 500.0,
+          '90th_percentile_vsync_frame_lag': 500.0,
+          '99th_percentile_vsync_frame_lag': 500.0,
           'average_cpu_usage': 40.0,
           '90th_percentile_cpu_usage': 60.0,
           '99th_percentile_cpu_usage': 60.0,
@@ -561,5 +581,64 @@ void main() {
         expect(summarizer.computePercentile(ProfileType.CPU, 90), 85.0);
       });
     });
+
+    group('VsyncFrameLagSummarizer tests', () {
+      VsyncFrameLagSummarizer summarize(List<Map<String, dynamic>> traceEvents) {
+        final Timeline timeline = Timeline.fromJson(<String, dynamic>{
+          'traceEvents': traceEvents,
+        });
+        return VsyncFrameLagSummarizer(timeline.events!);
+      }
+
+      test('average_vsync_frame_lag', () async {
+        final VsyncFrameLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          platformVsync(10),
+          vsyncCallback(12),
+          platformVsync(16),
+          vsyncCallback(29),
+        ]);
+        expect(summarizer.computeAverageVsyncFrameLag(), 7.5);
+      });
+
+      test('malformed_event_ordering', () async {
+        final VsyncFrameLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          vsyncCallback(10),
+          platformVsync(10),
+        ]);
+        expect(summarizer.computeAverageVsyncFrameLag(), 0);
+        expect(summarizer.computePercentileVsyncFrameLag(80), 0);
+      });
+
+      test('penalize_consecutive_vsyncs', () async {
+        final VsyncFrameLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          platformVsync(10),
+          platformVsync(12),
+        ]);
+        expect(summarizer.computeAverageVsyncFrameLag(), 2);
+      });
+
+      test('pick_nearest_platform_vsync', () async {
+        final VsyncFrameLagSummarizer summarizer = summarize(<Map<String, dynamic>>[
+          platformVsync(10),
+          platformVsync(12),
+          vsyncCallback(18),
+        ]);
+        expect(summarizer.computeAverageVsyncFrameLag(), 4);
+      });
+
+      test('percentile_vsync_frame_lag', () async {
+        final List<Map<String, dynamic>> events = <Map<String, dynamic>>[];
+        int ts = 100;
+        for (int i = 0; i < 100; i++) {
+          events.add(platformVsync(ts));
+          ts = ts + 10 * (i + 1);
+          events.add(vsyncCallback(ts));
+        }
+
+        final VsyncFrameLagSummarizer summarizer = summarize(events);
+        expect(summarizer.computePercentileVsyncFrameLag(90), 890);
+        expect(summarizer.computePercentileVsyncFrameLag(99), 990);
+      });
+    });
   });
 }