Add "Frame Request Pending" lag to collected metrics (flutter#135279)

This measures the wall clock time between a new frame being scheduled in dart code to the Vsync callback in the engine

It's an important source of lag which isn't shown in the top-level UI / Build time graphs, and can correlate with "invisible" missed/non-scheduled frames

I had to change a few unrelated timings in the test, it was only passing based on luck of sort order, and broke when I added more entries to the timeline.

Part of flutter#129150

Author: moffatman

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

@@ -0,0 +1,64 @@
+// 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';
+
+/// Event name for frame request pending timeline events.
+const String kFrameRequestPendingEvent = 'Frame Request Pending';
+
+/// Summarizes [TimelineEvents]s corresponding to [kFrameRequestPendingEvent] events.
+///
+/// `FrameRequestPendingLatency` is the time between `Animator::RequestFrame`
+/// and `Animator::BeginFrame` for each frame built by the Flutter engine.
+class FrameRequestPendingLatencySummarizer {
+  /// Creates a FrameRequestPendingLatencySummarizer given the timeline events.
+  FrameRequestPendingLatencySummarizer(this.frameRequestPendingEvents);
+
+  /// Timeline events with names in [kFrameRequestPendingTimelineEventNames].
+  final List<TimelineEvent> frameRequestPendingEvents;
+
+  /// Computes the average `FrameRequestPendingLatency` over the period of the timeline.
+  double computeAverageFrameRequestPendingLatency() {
+    final List<double> frameRequestPendingLatencies =
+        _computeFrameRequestPendingLatencies();
+    if (frameRequestPendingLatencies.isEmpty) {
+      return 0;
+    }
+
+    final double total = frameRequestPendingLatencies.reduce((double a, double b) => a + b);
+    return total / frameRequestPendingLatencies.length;
+  }
+
+  /// Computes the [percentile]-th percentile `FrameRequestPendingLatency` over the
+  /// period of the timeline.
+  double computePercentileFrameRequestPendingLatency(double percentile) {
+    final List<double> frameRequestPendingLatencies =
+        _computeFrameRequestPendingLatencies();
+    if (frameRequestPendingLatencies.isEmpty) {
+      return 0;
+    }
+    return findPercentile(frameRequestPendingLatencies, percentile);
+  }
+
+  List<double> _computeFrameRequestPendingLatencies() {
+    final List<double> result = <double>[];
+    final Map<String, int> starts = <String, int>{};
+    for (int i = 0; i < frameRequestPendingEvents.length; i++) {
+      final TimelineEvent event = frameRequestPendingEvents[i];
+      if (event.phase == 'b') {
+        final String? id = event.json['id'] as String?;
+        if (id != null) {
+          starts[id] = event.timestampMicros!;
+        }
+      } else if (event.phase == 'e') {
+        final int? start = starts[event.json['id']];
+        if (start != null) {
+          result.add((event.timestampMicros! - start).toDouble());
+        }
+      }
+    }
+    return result;
+  }
+}

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

@@ -9,6 +9,7 @@ import 'package:file/file.dart';
 import 'package:path/path.dart' as path;
 
 import 'common.dart';
+import 'frame_request_pending_latency_summarizer.dart';
 import 'gc_summarizer.dart';
 import 'percentile_utils.dart';
 import 'profiling_summarizer.dart';
@@ -258,13 +259,22 @@ class TimelineSummary {
   /// * "worst_picture_cache_memory": The worst (highest) value seen for the
   ///   memory used for the engine picture cache entries.
   ///   See [RasterCacheSummarizer.computeWorstPictureMemory].
+  /// * "average_frame_request_pending_latency": Computes the average of the delay
+  ///   between `Animator::RequestFrame` and `Animator::BeginFrame` in the engine.
+  ///   See [FrameRequestPendingLatencySummarizer.computeAverageFrameRequestPendingLatency].
+  /// * "90th_percentile_frame_request_pending_latency" and
+  ///   "99th_percentile_frame_request_pending_latency": The 90/99-th percentile
+  ///   delay between `Animator::RequestFrame` and `Animator::BeginFrame` in the
+  ///   engine.
+  ///   See [FrameRequestPendingLatencySummarizer.computePercentileFrameRequestPendingLatency].
   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 FrameRequestPendingLatencySummarizer frameRequestPendingLatencySummarizer = _frameRequestPendingLatencySummarizer();
 
     final Map<String, dynamic> timelineSummary = <String, dynamic>{
       'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(),
@@ -303,6 +313,9 @@ class TimelineSummary {
       'average_layer_cache_count': rasterCacheSummarizer.computeAverageLayerCount(),
       '90th_percentile_layer_cache_count': rasterCacheSummarizer.computePercentileLayerCount(90.0),
       '99th_percentile_layer_cache_count': rasterCacheSummarizer.computePercentileLayerCount(99.0),
+      'average_frame_request_pending_latency': frameRequestPendingLatencySummarizer.computeAverageFrameRequestPendingLatency(),
+      '90th_percentile_frame_request_pending_latency': frameRequestPendingLatencySummarizer.computePercentileFrameRequestPendingLatency(90.0),
+      '99th_percentile_frame_request_pending_latency': frameRequestPendingLatencySummarizer.computePercentileFrameRequestPendingLatency(99.0),
       'worst_layer_cache_count': rasterCacheSummarizer.computeWorstLayerCount(),
       'average_layer_cache_memory': rasterCacheSummarizer.computeAverageLayerMemory(),
       '90th_percentile_layer_cache_memory': rasterCacheSummarizer.computePercentileLayerMemory(90.0),
@@ -491,5 +504,7 @@ class TimelineSummary {
 
   RasterCacheSummarizer _rasterCacheSummarizer() => RasterCacheSummarizer(_extractNamedEvents(kRasterCacheEvent));
 
+  FrameRequestPendingLatencySummarizer _frameRequestPendingLatencySummarizer() => FrameRequestPendingLatencySummarizer(_extractNamedEvents(kFrameRequestPendingEvent));
+
   GCSummarizer _gcSummarizer() => GCSummarizer.fromEvents(_extractEventsWithNames(kGCRootEvents));
 }

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

@@ -143,6 +143,20 @@ void main() {
       return result;
     }
 
+    Map<String, dynamic> frameRequestPendingStart(String id, int timeStamp) => <String, dynamic>{
+      'name': 'Frame Request Pending',
+      'ph': 'b',
+      'id': id,
+      'ts': timeStamp,
+    };
+
+    Map<String, dynamic> frameRequestPendingEnd(String id, int timeStamp) => <String, dynamic>{
+      'name': 'Frame Request Pending',
+      'ph': 'e',
+      'id': id,
+      'ts': timeStamp,
+    };
+
     group('frame_count', () {
       test('counts frames', () {
         expect(
@@ -448,13 +462,19 @@ void main() {
         expect(
           summarize(<Map<String, dynamic>>[
             begin(1000), end(19000),
-            begin(19000), end(29000),
-            begin(29000), end(49000),
+            begin(19001), end(29001),
+            begin(29002), end(49002),
             ...newGenGC(4, 10, 100),
             ...oldGenGC(5, 10000, 100),
             frameBegin(1000), frameEnd(18000),
             frameBegin(19000), frameEnd(28000),
             frameBegin(29000), frameEnd(48000),
+            frameRequestPendingStart('1', 1000),
+            frameRequestPendingEnd('1', 2000),
+            frameRequestPendingStart('2', 3000),
+            frameRequestPendingEnd('2', 5000),
+            frameRequestPendingStart('3', 6000),
+            frameRequestPendingEnd('3', 9000),
           ]).summaryJson,
           <String, dynamic>{
             'average_frame_build_time_millis': 15.0,
@@ -475,7 +495,7 @@ void main() {
             'frame_build_times': <int>[17000, 9000, 19000],
             'frame_rasterizer_times': <int>[18000, 10000, 20000],
             'frame_begin_times': <int>[0, 18000, 28000],
-            'frame_rasterizer_begin_times': <int>[0, 18000, 28000],
+            'frame_rasterizer_begin_times': <int>[0, 18001, 28002],
             'average_vsync_transitions_missed': 0.0,
             '90th_percentile_vsync_transitions_missed': 0.0,
             '99th_percentile_vsync_transitions_missed': 0.0,
@@ -505,6 +525,9 @@ void main() {
             '90hz_frame_percentage': 0,
             '120hz_frame_percentage': 0,
             'illegal_refresh_rate_frame_count': 0,
+            'average_frame_request_pending_latency': 2000.0,
+            '90th_percentile_frame_request_pending_latency': 3000.0,
+            '99th_percentile_frame_request_pending_latency': 3000.0,
           },
         );
       });
@@ -556,8 +579,8 @@ void main() {
       test('writes summary to JSON file', () async {
         await summarize(<Map<String, dynamic>>[
           begin(1000), end(19000),
-          begin(19000), end(29000),
-          begin(29000), end(49000),
+          begin(19001), end(29001),
+          begin(29002), end(49002),
           frameBegin(1000), frameEnd(18000),
           frameBegin(19000), frameEnd(28000),
           frameBegin(29000), frameEnd(48000),
@@ -569,6 +592,12 @@ void main() {
           cpuUsage(5000, 20), cpuUsage(5010, 60),
           memoryUsage(6000, 20, 40), memoryUsage(6100, 30, 45),
           platformVsync(7000), vsyncCallback(7500),
+          frameRequestPendingStart('1', 1000),
+          frameRequestPendingEnd('1', 2000),
+          frameRequestPendingStart('2', 3000),
+          frameRequestPendingEnd('2', 5000),
+          frameRequestPendingStart('3', 6000),
+          frameRequestPendingEnd('3', 9000),
         ]).writeTimelineToFile('test', destinationDirectory: tempDir.path);
         final String written =
             await fs.file(path.join(tempDir.path, 'test.timeline_summary.json')).readAsString();
@@ -591,7 +620,7 @@ void main() {
           'frame_build_times': <int>[17000, 9000, 19000],
           'frame_rasterizer_times': <int>[18000, 10000, 20000],
           'frame_begin_times': <int>[0, 18000, 28000],
-          'frame_rasterizer_begin_times': <int>[0, 18000, 28000],
+          'frame_rasterizer_begin_times': <int>[0, 18001, 28002],
           'average_vsync_transitions_missed': 8.0,
           '90th_percentile_vsync_transitions_missed': 12.0,
           '99th_percentile_vsync_transitions_missed': 12.0,
@@ -627,6 +656,9 @@ void main() {
           '90hz_frame_percentage': 0,
           '120hz_frame_percentage': 0,
           'illegal_refresh_rate_frame_count': 0,
+          'average_frame_request_pending_latency': 2000.0,
+          '90th_percentile_frame_request_pending_latency': 3000.0,
+          '99th_percentile_frame_request_pending_latency': 3000.0,
         });
       });
     });