redux of a change to use new engine APIs for Flutter.Frame events (#34365)

dev/devicelab/bin/tasks/service_extensions_test.dart

@@ -6,12 +6,11 @@ import 'dart:async';
 import 'dart:convert';
 import 'dart:io';
 
-import 'package:path/path.dart' as path;
-import 'package:vm_service_client/vm_service_client.dart';
-
 import 'package:flutter_devicelab/framework/adb.dart';
 import 'package:flutter_devicelab/framework/framework.dart';
 import 'package:flutter_devicelab/framework/utils.dart';
+import 'package:path/path.dart' as path;
+import 'package:vm_service_client/vm_service_client.dart';
 
 void main() {
   task(() async {
@@ -57,10 +56,19 @@ void main() {
       final VMServiceClient client = VMServiceClient.connect('ws://localhost:$vmServicePort/ws');
       final VM vm = await client.getVM();
       final VMIsolateRef isolate = vm.isolates.first;
-      final Stream<VMExtensionEvent> frameEvents = isolate.onExtensionEvent.where(
-              (VMExtensionEvent e) => e.kind == 'Flutter.Frame');
-      final Stream<VMExtensionEvent> navigationEvents = isolate.onExtensionEvent.where(
-              (VMExtensionEvent e) => e.kind == 'Flutter.Navigation');
+
+      final StreamController<VMExtensionEvent> frameEventsController = StreamController<VMExtensionEvent>();
+      final StreamController<VMExtensionEvent> navigationEventsController = StreamController<VMExtensionEvent>();
+      isolate.onExtensionEvent.listen((VMExtensionEvent event) {
+        if (event.kind == 'Flutter.Frame') {
+          frameEventsController.add(event);
+        } else if (event.kind == 'Flutter.Navigation') {
+          navigationEventsController.add(event);
+        }
+      });
+
+      final Stream<VMExtensionEvent> frameEvents = frameEventsController.stream;
+      final Stream<VMExtensionEvent> navigationEvents = navigationEventsController.stream;
 
       print('reassembling app...');
       final Future<VMExtensionEvent> frameFuture = frameEvents.first;
@@ -71,13 +79,17 @@ void main() {
       print('${event.kind}: ${event.data}');
 
       // validate the fields
-      // {number: 8, startTime: 0, elapsed: 1437}
+      // {number: 8, startTime: 0, elapsed: 1437, build: 600, raster: 800}
       expect(event.data['number'] is int);
       expect(event.data['number'] >= 0);
       expect(event.data['startTime'] is int);
       expect(event.data['startTime'] >= 0);
       expect(event.data['elapsed'] is int);
       expect(event.data['elapsed'] >= 0);
+      expect(event.data['build'] is int);
+      expect(event.data['build'] >= 0);
+      expect(event.data['raster'] is int);
+      expect(event.data['raster'] >= 0);
 
       final Future<VMExtensionEvent> navigationFuture = navigationEvents.first;
       // This tap triggers a navigation event.

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

@@ -4,8 +4,8 @@
 
 import 'dart:async';
 import 'dart:collection';
-import 'dart:developer';
-import 'dart:ui' show AppLifecycleState;
+import 'dart:developer' show Flow, Timeline;
+import 'dart:ui' show AppLifecycleState, FramePhase, FrameTiming;
 
 import 'package:collection/collection.dart' show PriorityQueue, HeapPriorityQueue;
 import 'package:flutter/foundation.dart';
@@ -198,6 +198,17 @@ mixin SchedulerBinding on BindingBase, ServicesBinding {
     window.onDrawFrame = _handleDrawFrame;
     SystemChannels.lifecycle.setMessageHandler(_handleLifecycleMessage);
     readInitialLifecycleStateFromNativeWindow();
+
+    if (!kReleaseMode) {
+      int frameNumber = 0;
+
+      window.onReportTimings = (List<FrameTiming> timings) {
+        for (FrameTiming frameTiming in timings) {
+          frameNumber += 1;
+          _profileFramePostEvent(frameNumber, frameTiming);
+        }
+      };
+    }
   }
 
   /// The current [SchedulerBinding], if one has been created.
@@ -842,8 +853,7 @@ mixin SchedulerBinding on BindingBase, ServicesBinding {
   }
   Duration _currentFrameTimeStamp;
 
-  int _profileFrameNumber = 0;
-  final Stopwatch _profileFrameStopwatch = Stopwatch();
+  int _debugFrameNumber = 0;
   String _debugBanner;
   bool _ignoreNextEngineDrawFrame = false;
 
@@ -894,13 +904,9 @@ mixin SchedulerBinding on BindingBase, ServicesBinding {
     if (rawTimeStamp != null)
       _lastRawTimeStamp = rawTimeStamp;
 
-    if (!kReleaseMode) {
-      _profileFrameNumber += 1;
-      _profileFrameStopwatch.reset();
-      _profileFrameStopwatch.start();
-    }
-
     assert(() {
+      _debugFrameNumber += 1;
+
       if (debugPrintBeginFrameBanner || debugPrintEndFrameBanner) {
         final StringBuffer frameTimeStampDescription = StringBuffer();
         if (rawTimeStamp != null) {
@@ -908,7 +914,7 @@ mixin SchedulerBinding on BindingBase, ServicesBinding {
         } else {
           frameTimeStampDescription.write('(warm-up frame)');
         }
-        _debugBanner = '▄▄▄▄▄▄▄▄ Frame ${_profileFrameNumber.toString().padRight(7)}   ${frameTimeStampDescription.toString().padLeft(18)} ▄▄▄▄▄▄▄▄';
+        _debugBanner = '▄▄▄▄▄▄▄▄ Frame ${_debugFrameNumber.toString().padRight(7)}   ${frameTimeStampDescription.toString().padLeft(18)} ▄▄▄▄▄▄▄▄';
         if (debugPrintBeginFrameBanner)
           debugPrint(_debugBanner);
       }
@@ -961,10 +967,6 @@ mixin SchedulerBinding on BindingBase, ServicesBinding {
     } finally {
       _schedulerPhase = SchedulerPhase.idle;
       Timeline.finishSync(); // end the Frame
-      if (!kReleaseMode) {
-        _profileFrameStopwatch.stop();
-        _profileFramePostEvent();
-      }
       assert(() {
         if (debugPrintEndFrameBanner)
           debugPrint('▀' * _debugBanner.length);
@@ -975,11 +977,13 @@ mixin SchedulerBinding on BindingBase, ServicesBinding {
     }
   }
 
-  void _profileFramePostEvent() {
+  void _profileFramePostEvent(int frameNumber, FrameTiming frameTiming) {
     postEvent('Flutter.Frame', <String, dynamic>{
-      'number': _profileFrameNumber,
-      'startTime': _currentFrameTimeStamp.inMicroseconds,
-      'elapsed': _profileFrameStopwatch.elapsedMicroseconds,
+      'number': frameNumber,
+      'startTime': frameTiming.timestampInMicroseconds(FramePhase.buildStart),
+      'elapsed': frameTiming.totalSpan.inMicroseconds,
+      'build': frameTiming.buildDuration.inMicroseconds,
+      'raster': frameTiming.rasterDuration.inMicroseconds,
     });
   }
 

packages/flutter/test/scheduler/scheduler_test.dart

@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 import 'dart:async';
+import 'dart:ui' show window, FrameTiming;
 
 import 'package:flutter/foundation.dart';
 import 'package:flutter/scheduler.dart';
@@ -10,7 +11,18 @@ import 'package:flutter/services.dart';
 
 import '../flutter_test_alternative.dart';
 
-class TestSchedulerBinding extends BindingBase with ServicesBinding, SchedulerBinding { }
+class TestSchedulerBinding extends BindingBase with ServicesBinding, SchedulerBinding {
+  final Map<String, List<Map<String, dynamic>>> eventsDispatched = <String, List<Map<String, dynamic>>>{};
+
+  @override
+  void postEvent(String eventKind, Map<dynamic, dynamic> eventData) {
+    getEventsDispatched(eventKind).add(eventData);
+  }
+
+  List<Map<String, dynamic>> getEventsDispatched(String eventKind) {
+    return eventsDispatched.putIfAbsent(eventKind, () => <Map<String, dynamic>>[]);
+  }
+}
 
 class TestStrategy {
   int allowedPriority = 10000;
@@ -21,7 +33,8 @@ class TestStrategy {
 }
 
 void main() {
-  SchedulerBinding scheduler;
+  TestSchedulerBinding scheduler;
+
   setUpAll(() {
     scheduler = TestSchedulerBinding();
   });
@@ -116,4 +129,23 @@ void main() {
     expect(timerQueueTasks.length, 2);
     expect(taskExecuted, false);
   });
+
+  test('Flutter.Frame event fired', () async {
+    window.onReportTimings(<FrameTiming>[FrameTiming(<int>[
+      // build start, build finish
+      10000, 15000,
+      // raster start, raster finish
+      16000, 20000,
+    ])]);
+
+    final List<Map<String, dynamic>> events = scheduler.getEventsDispatched('Flutter.Frame');
+    expect(events, hasLength(1));
+
+    final Map<String, dynamic> event = events.first;
+    expect(event['number'], isNonNegative);
+    expect(event['startTime'], 10000);
+    expect(event['elapsed'], 10000);
+    expect(event['build'], 5000);
+    expect(event['raster'], 4000);
+  });
 }