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

This relands https://github.com/flutter/flutter/pull/35297

The followings have been done to fix the broken tests:
  1. Add `didSendFirstFrameRasterizedEvent` extension and its tests
  2. Wait for `didSendFirstFrameRasterizedEvent` instead of
     `didSendFirstFrameEvent` during start up tests
  3. Mark missed (probably newly added) start up tests as flaky

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

@@ -244,12 +244,14 @@ tasks:
     description: >
       Verifies that Platform View can be used from an Android project.
     stage: devicelab
+    flaky: true
     required_agent_capabilities: ["mac/android"]
 
   complex_layout__start_up:
     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:
@@ -293,6 +295,7 @@ tasks:
     description: >
       Verifies that Flutter View can be used from an Android project.
     stage: devicelab
+    flaky: true
     required_agent_capabilities: ["mac/android"]
 
   integration_ui:
@@ -434,6 +437,7 @@ tasks:
     description: >
       Verifies that Platform View can be used from an iOS project.
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios"]
 
   complex_layout_scroll_perf_ios__timeline_summary:
@@ -447,12 +451,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:
@@ -460,6 +466,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:
@@ -479,6 +486,7 @@ tasks:
     description: >
       Verifies that Flutter View can be used from an iOS project.
     stage: devicelab_ios
+    flaky: true
     required_agent_capabilities: ["mac/ios"]
 
   integration_ui_ios:
@@ -564,6 +572,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:
@@ -571,6 +580,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:
@@ -578,6 +588,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:
@@ -616,6 +627,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:
@@ -623,6 +635,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';
@@ -304,6 +304,20 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB
         },
       );
 
+      // This returns 'true' when the first frame is rasterized, and the trace
+      // event 'Rasterized first useful frame' is sent out.
+      registerServiceExtension(
+        name: 'didSendFirstFrameRasterizedEvent',
+        callback: (_) async {
+          return <String, dynamic>{
+            // This is defined to return a STRING, not a boolean.
+            // Devtools, the Intellij plugin, and the flutter tool all depend
+            // on it returning a string and not a boolean.
+            'enabled': firstFrameRasterized ? 'true' : 'false',
+          };
+        },
+      );
+
       // Expose the ability to send Widget rebuilds as [Timeline] events.
       registerBoolServiceExtension(
         name: 'profileWidgetBuilds',
@@ -550,7 +564,30 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB
   int _deferFirstFrameReportCount = 0;
   bool get _reportFirstFrame => _deferFirstFrameReportCount == 0;
 
-  /// Whether the first frame has finished rendering.
+
+  final Completer<void> _firstFrameCompleter = Completer<void>();
+
+  /// Whether the Flutter engine has rasterized the first frame.
+  ///
+  /// {@macro flutter.frame_rasterized_vs_presented}
+  ///
+  /// See also:
+  ///
+  ///  * [waitUntilFirstFrameRasterized], the future when [firstFrameRasterized]
+  ///    becomes true.
+  bool get firstFrameRasterized => _firstFrameCompleter.isCompleted;
+
+  /// A future that completes when the Flutter engine has rasterized the first
+  /// frame.
+  ///
+  /// {@macro flutter.frame_rasterize_vs_presented}
+  ///
+  /// See also:
+  ///
+  ///  * [firstFrameRasterized], whether this future has completed or not.
+  Future<void> get waitUntilFirstFrameRasterized => _firstFrameCompleter.future;
+
+  /// Whether the first frame has finished building.
   ///
   /// Only useful in profile and debug builds; in release builds, this always
   /// return false. This can be deferred using [deferFirstFrameReport] and
@@ -559,6 +596,10 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB
   ///
   /// This value can also be obtained over the VM service protocol as
   /// `ext.flutter.didSendFirstFrameEvent`.
+  ///
+  /// See also:
+  ///
+  ///  * [firstFrameRasterized], whether the first frame has finished rendering.
   bool get debugDidSendFirstFrameEvent => !_needToReportFirstFrame;
 
   /// Tell the framework not to report the frame it is building as a "useful"
@@ -696,6 +737,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 +768,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
@@ -130,12 +132,20 @@ void main() {
     firstFrameResult = await binding.testExtension('didSendFirstFrameEvent', <String, String>{});
     expect(firstFrameResult, <String, String>{'enabled': 'false'});
 
+    expect(binding.firstFrameRasterized, isFalse);
+    firstFrameResult = await binding.testExtension('didSendFirstFrameRasterizedEvent', <String, String>{});
+    expect(firstFrameResult, <String, String>{'enabled': 'false'});
+
     await binding.doFrame(); // initial frame scheduled by creating the binding
 
     expect(binding.debugDidSendFirstFrameEvent, isTrue);
     firstFrameResult = await binding.testExtension('didSendFirstFrameEvent', <String, String>{});
     expect(firstFrameResult, <String, String>{'enabled': 'true'});
 
+    expect(binding.firstFrameRasterized, isTrue);
+    firstFrameResult = await binding.testExtension('didSendFirstFrameRasterizedEvent', <String, String>{});
+    expect(firstFrameResult, <String, String>{'enabled': 'true'});
+
     expect(binding.frameScheduled, isFalse);
 
     expect(debugPrint, equals(debugPrintThrottled));
@@ -156,7 +166,7 @@ void main() {
 
     // If you add a service extension... TEST IT! :-)
     // ...then increment this number.
-    expect(binding.extensions.length, 26 + widgetInspectorExtensionCount);
+    expect(binding.extensions.length, 27 + widgetInspectorExtensionCount);
 
     expect(console, isEmpty);
     debugPrint = debugPrintThrottled;

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.waitUntilFirstFrameRasterized;
+    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));

packages/flutter_tools/lib/src/vmservice.dart

@@ -1313,7 +1313,7 @@ class Isolate extends ServiceObjectOwner {
   }
 
   Future<bool> flutterAlreadyPaintedFirstUsefulFrame() async {
-    final Map<String, dynamic> result = await invokeFlutterExtensionRpcRaw('ext.flutter.didSendFirstFrameEvent');
+    final Map<String, dynamic> result = await invokeFlutterExtensionRpcRaw('ext.flutter.didSendFirstFrameRasterizedEvent');
     // result might be null when the service extension is not initialized
     return result != null && result['enabled'] == 'true';
   }