Fix the first frame logic in tracing and driver (#35297)

This should fix https://github.com/flutter/flutter/issues/31442 and https://github.com/flutter/flutter/issues/34867

dev/benchmarks/complex_layout/test_driver/scroll_perf_test.dart

@@ -13,6 +13,9 @@ void main() {
 
     setUpAll(() async {
       driver = await FlutterDriver.connect();
+
+      // TODO(liyuqian): enable the following once it's proved to be non-flaky by transition_perf_test.dart.
+      // await driver.waitUntilFirstFrameRasterized();
     });
 
     tearDownAll(() async {

dev/devicelab/lib/tasks/perf_tests.dart

@@ -159,6 +159,7 @@ class StartupTest {
 
       return TaskResult.success(data, benchmarkScoreKeys: <String>[
         'timeToFirstFrameMicros',
+        'timeToFirstFrameRasterizedMicros',
       ]);
     });
   }

dev/devicelab/manifest.yaml

@@ -251,6 +251,7 @@ tasks:
     description: >
       Measures the startup time of the Complex Layout sample app on Android.
     stage: devicelab
+    flaky: true
     required_agent_capabilities: ["mac/android"]
 
   hot_mode_dev_cycle__benchmark:
@@ -448,12 +449,14 @@ tasks:
     description: >
       Measures the startup time of the Flutter Gallery app on iPhone 6.
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios"]
 
   complex_layout_ios__start_up:
     description: >
       Measures the startup time of the Complex Layout sample app on iPhone 6.
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios"]
 
   flutter_gallery_ios__transition_perf:
@@ -461,6 +464,7 @@ tasks:
       Measures the performance of screen transitions in Flutter Gallery on
       iOS.
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios"]
 
   hello_world_ios__compile:
@@ -565,6 +569,7 @@ tasks:
     description: >
       Measures the startup time of the Flutter Gallery app on Android.
     stage: devicelab
+    flaky: true
     required_agent_capabilities: ["linux/android"]
 
   flutter_gallery__transition_perf:
@@ -572,6 +577,7 @@ tasks:
       Measures the performance of screen transitions in Flutter Gallery on
       Android.
     stage: devicelab
+    flaky: true
     required_agent_capabilities: ["linux/android"]
 
   flutter_gallery__transition_perf_with_semantics:
@@ -579,6 +585,7 @@ tasks:
       Measures the delta in performance of screen transitions without and
       with semantics enabled.
     stage: devicelab
+    flaky: true
     required_agent_capabilities: ["linux/android"]
 
   flutter_gallery__memory_nav:
@@ -617,6 +624,7 @@ tasks:
     description: >
       Measures the startup time of the Flutter Gallery app on 32-bit iOS (iPhone 4S).
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios32"]
 
   flutter_gallery_ios32__transition_perf:
@@ -624,6 +632,7 @@ tasks:
       Measures the performance of screen transitions in Flutter Gallery on
       32-bit iOS (iPhone 4S).
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios32"]
 
   run_without_leak_mac:

examples/flutter_gallery/test_driver/scroll_perf_test.dart

@@ -13,6 +13,9 @@ void main() {
 
     setUpAll(() async {
       driver = await FlutterDriver.connect();
+
+      // TODO(liyuqian): enable the following once it's proved to be non-flaky by transition_perf_test.dart.
+      // await driver.waitUntilFirstFrameRasterized();
     });
 
     tearDownAll(() async {

examples/flutter_gallery/test_driver/transitions_perf_test.dart

@@ -183,6 +183,9 @@ void main([List<String> args = const <String>[]]) {
     setUpAll(() async {
       driver = await FlutterDriver.connect();
 
+      // Wait for the first frame to be rasterized.
+      await driver.waitUntilFirstFrameRasterized();
+
       if (args.contains('--with_semantics')) {
         print('Enabeling semantics...');
         await driver.setSemantics(true);
@@ -200,7 +203,6 @@ void main([List<String> args = const <String>[]]) {
     });
 
     test('all demos', () async {
-
       // Collect timeline data for just a limited set of demos to avoid OOMs.
       final Timeline timeline = await driver.traceAction(
         () async {

packages/flutter/lib/src/widgets/binding.dart

@@ -4,7 +4,7 @@
 
 import 'dart:async';
 import 'dart:developer' as developer;
-import 'dart:ui' show AppLifecycleState, Locale, AccessibilityFeatures;
+import 'dart:ui' show AppLifecycleState, Locale, AccessibilityFeatures, FrameTiming, TimingsCallback;
 
 import 'package:flutter/foundation.dart';
 import 'package:flutter/gestures.dart';
@@ -550,6 +550,14 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB
   int _deferFirstFrameReportCount = 0;
   bool get _reportFirstFrame => _deferFirstFrameReportCount == 0;
 
+
+  final Completer<void> _firstFrameCompleter = Completer<void>();
+
+  /// Whether the Flutter engine has rasterized the first frame.
+  ///
+  /// {@macro flutter.frame_rasterized_vs_presented}
+  Future<void> get firstFrameRasterized => _firstFrameCompleter.future;
+
   /// Whether the first frame has finished rendering.
   ///
   /// Only useful in profile and debug builds; in release builds, this always
@@ -696,6 +704,24 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB
       debugBuildingDirtyElements = true;
       return true;
     }());
+
+    if (_needToReportFirstFrame && _reportFirstFrame) {
+      assert(!_firstFrameCompleter.isCompleted);
+      // TODO(liyuqian): use a broadcast stream approach
+      final TimingsCallback oldCallback = WidgetsBinding.instance.window.onReportTimings;
+      WidgetsBinding.instance.window.onReportTimings = (List<FrameTiming> timings) {
+        if (!kReleaseMode) {
+          developer.Timeline.instantSync('Rasterized first useful frame');
+          developer.postEvent('Flutter.FirstFrame', <String, dynamic>{});
+        }
+        if (oldCallback != null) {
+          oldCallback(timings);
+        }
+        WidgetsBinding.instance.window.onReportTimings = oldCallback;
+        _firstFrameCompleter.complete();
+      };
+    }
+
     try {
       if (renderViewElement != null)
         buildOwner.buildScope(renderViewElement);
@@ -709,11 +735,10 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB
     }
     if (!kReleaseMode) {
       if (_needToReportFirstFrame && _reportFirstFrame) {
-        developer.Timeline.instantSync('Widgets completed first useful frame');
-        developer.postEvent('Flutter.FirstFrame', <String, dynamic>{});
-        _needToReportFirstFrame = false;
+        developer.Timeline.instantSync('Widgets built first useful frame');
       }
     }
+    _needToReportFirstFrame = false;
   }
 
   /// The [Element] that is at the root of the hierarchy (and which wraps the

packages/flutter/test/foundation/service_extensions_test.dart

@@ -79,6 +79,8 @@ class TestServiceExtensionsBinding extends BindingBase
     await flushMicrotasks();
     if (ui.window.onDrawFrame != null)
       ui.window.onDrawFrame();
+    if (ui.window.onReportTimings != null)
+      ui.window.onReportTimings(<ui.FrameTiming>[]);
   }
 
   @override

packages/flutter_driver/lib/src/common/find.dart

@@ -132,6 +132,26 @@ class WaitUntilNoPendingFrame extends Command {
   String get kind => 'waitUntilNoPendingFrame';
 }
 
+/// A Flutter Driver command that waits until the Flutter engine rasterizes the
+/// first frame.
+///
+/// {@template flutter.frame_rasterized_vs_presented}
+/// Usually, the time that a frame is rasterized is very close to the time that
+/// it gets presented on the display. Specifically, rasterization is the last
+/// expensive phase of a frame that's still in Flutter's control.
+/// {@endtemplate}
+class WaitUntilFirstFrameRasterized extends Command {
+  /// Creates this command.
+  const WaitUntilFirstFrameRasterized({ Duration timeout }) : super(timeout: timeout);
+
+  /// Deserializes this command from the value generated by [serialize].
+  WaitUntilFirstFrameRasterized.deserialize(Map<String, String> json)
+      : super.deserialize(json);
+
+  @override
+  String get kind => 'waitUntilFirstFrameRasterized';
+}
+
 /// Base class for Flutter Driver finders, objects that describe how the driver
 /// should search for elements.
 abstract class SerializableFinder {

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

@@ -499,6 +499,14 @@ class FlutterDriver {
     await _sendCommand(WaitUntilNoTransientCallbacks(timeout: timeout));
   }
 
+  /// Waits until the next [Window.onReportTimings] is called.
+  ///
+  /// Use this method to wait for the first frame to be rasterized during the
+  /// app launch.
+  Future<void> waitUntilFirstFrameRasterized() async {
+    await _sendCommand(const WaitUntilFirstFrameRasterized());
+  }
+
   Future<DriverOffset> _getOffset(SerializableFinder finder, OffsetType type, { Duration timeout }) async {
     final GetOffset command = GetOffset(finder, type, timeout: timeout);
     final GetOffsetResult result = GetOffsetResult.fromJson(await _sendCommand(command));

packages/flutter_driver/lib/src/extension/extension.dart

@@ -114,6 +114,7 @@ class FlutterDriverExtension {
       'waitForAbsent': _waitForAbsent,
       'waitUntilNoTransientCallbacks': _waitUntilNoTransientCallbacks,
       'waitUntilNoPendingFrame': _waitUntilNoPendingFrame,
+      'waitUntilFirstFrameRasterized': _waitUntilFirstFrameRasterized,
       'get_semantics_id': _getSemanticsId,
       'get_offset': _getOffset,
       'get_diagnostics_tree': _getDiagnosticsTree,
@@ -135,6 +136,7 @@ class FlutterDriverExtension {
       'waitForAbsent': (Map<String, String> params) => WaitForAbsent.deserialize(params),
       'waitUntilNoTransientCallbacks': (Map<String, String> params) => WaitUntilNoTransientCallbacks.deserialize(params),
       'waitUntilNoPendingFrame': (Map<String, String> params) => WaitUntilNoPendingFrame.deserialize(params),
+      'waitUntilFirstFrameRasterized': (Map<String, String> params) => WaitUntilFirstFrameRasterized.deserialize(params),
       'get_semantics_id': (Map<String, String> params) => GetSemanticsId.deserialize(params),
       'get_offset': (Map<String, String> params) => GetOffset.deserialize(params),
       'get_diagnostics_tree': (Map<String, String> params) => GetDiagnosticsTree.deserialize(params),
@@ -220,6 +222,12 @@ class FlutterDriverExtension {
     return RenderTree(RendererBinding.instance?.renderView?.toStringDeep());
   }
 
+  // This can be used to wait for the first frame being rasterized during app launch.
+  Future<Result> _waitUntilFirstFrameRasterized(Command command) async {
+    await WidgetsBinding.instance.firstFrameRasterized;
+    return null;
+  }
+
   // Waits until at the end of a frame the provided [condition] is [true].
   Future<void> _waitUntilFrame(bool condition(), [ Completer<void> completer ]) {
     completer ??= Completer<void>();

packages/flutter_tools/lib/src/tracing.dart

@@ -14,12 +14,13 @@ import 'vmservice.dart';
 // Names of some of the Timeline events we care about.
 const String _kFlutterEngineMainEnterEventName = 'FlutterEngineMainEnter';
 const String _kFrameworkInitEventName = 'Framework initialization';
-const String _kFirstUsefulFrameEventName = 'Widgets completed first useful frame';
+const String _kFirstFrameBuiltEventName = 'Widgets built first useful frame';
+const String _kFirstFrameRasterizedEventName = 'Rasterized first useful frame';
 
 class Tracing {
   Tracing(this.vmService);
 
-  static const String firstUsefulFrameEventName = _kFirstUsefulFrameEventName;
+  static const String firstUsefulFrameEventName = _kFirstFrameRasterizedEventName;
 
   static Future<Tracing> connect(Uri uri) async {
     final VMService observatory = await VMService.connect(uri);
@@ -47,7 +48,7 @@ class Tracing {
         (await vmService.onTimelineEvent).listen((ServiceEvent timelineEvent) {
           final List<Map<String, dynamic>> events = timelineEvent.timelineEvents;
           for (Map<String, dynamic> event in events) {
-            if (event['name'] == _kFirstUsefulFrameEventName)
+            if (event['name'] == firstUsefulFrameEventName)
               whenFirstFrameRendered.complete();
           }
         });
@@ -122,16 +123,23 @@ Future<void> downloadStartupTrace(VMService observatory, { bool awaitFirstFrame
   }
 
   if (awaitFirstFrame) {
-    final int firstFrameTimestampMicros = extractInstantEventTimestamp(_kFirstUsefulFrameEventName);
-    if (firstFrameTimestampMicros == null) {
-      printTrace('First frame event is missing in the timeline: $timeline');
-      throw 'First frame event is missing in the timeline. Cannot compute startup time.';
+    final int firstFrameBuiltTimestampMicros = extractInstantEventTimestamp(_kFirstFrameBuiltEventName);
+    final int firstFrameRasterizedTimestampMicros = extractInstantEventTimestamp(_kFirstFrameRasterizedEventName);
+    if (firstFrameBuiltTimestampMicros == null || firstFrameRasterizedTimestampMicros == null) {
+      printTrace('First frame events are missing in the timeline: $timeline');
+      throw 'First frame events are missing in the timeline. Cannot compute startup time.';
     }
-    final int timeToFirstFrameMicros = firstFrameTimestampMicros - engineEnterTimestampMicros;
+
+    // To keep our old benchmarks valid, we'll preserve the
+    // timeToFirstFrameMicros as the firstFrameBuiltTimestampMicros.
+    // Additionally, we add timeToFirstFrameRasterizedMicros for a more accurate
+    // benchmark.
+    traceInfo['timeToFirstFrameRasterizedMicros'] = firstFrameRasterizedTimestampMicros - engineEnterTimestampMicros;
+    final int timeToFirstFrameMicros = firstFrameBuiltTimestampMicros - engineEnterTimestampMicros;
     traceInfo['timeToFirstFrameMicros'] = timeToFirstFrameMicros;
     message = 'Time to first frame: ${timeToFirstFrameMicros ~/ 1000}ms.';
     if (frameworkInitTimestampMicros != null)
-      traceInfo['timeAfterFrameworkInitMicros'] = firstFrameTimestampMicros - frameworkInitTimestampMicros;
+      traceInfo['timeAfterFrameworkInitMicros'] = firstFrameBuiltTimestampMicros - frameworkInitTimestampMicros;
   }
 
   traceInfoFile.writeAsStringSync(toPrettyJson(traceInfo));