fire service protocol extension events for frames (flutter#10966)

* fire service protocol extension events for frames

* start time in micros

* introduce a profile() function; only send frame events when in profile (or debug) modes

* moved the profile() function to foundation/profile.dart

* refactor to make the change more testable; test the change

* fire service protocol events by listening to onFrameInfo

* remove the frame event stream; add a devicelab test

* remove a todo

* final

Author: devoncarew

dev/devicelab/bin/tasks/service_extensions_test.dart

@@ -0,0 +1,88 @@
+// Copyright (c) 2017 The Chromium 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 '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';
+
+const int kObservatoryPort = 8888;
+
+void main() {
+  task(() async {
+    final Device device = await devices.workingDevice;
+    await device.unlock();
+    final Directory appDir = dir(path.join(flutterDirectory.path, 'dev/integration_tests/ui'));
+    await inDirectory(appDir, () async {
+      final Completer<Null> ready = new Completer<Null>();
+      bool ok;
+      print('run: starting...');
+      final Process run = await startProcess(
+        path.join(flutterDirectory.path, 'bin', 'flutter'),
+        <String>['run', '--verbose', '--observatory-port=$kObservatoryPort', '-d', device.deviceId, 'lib/main.dart'],
+      );
+      run.stdout
+        .transform(UTF8.decoder)
+        .transform(const LineSplitter())
+        .listen((String line) {
+          print('run:stdout: $line');
+          if (line.contains(new RegExp(r'^\[\s+\] For a more detailed help message, press "h"\. To quit, press "q"\.'))) {
+            print('run: ready!');
+            ready.complete();
+            ok ??= true;
+          }
+        });
+      run.stderr
+        .transform(UTF8.decoder)
+        .transform(const LineSplitter())
+        .listen((String line) {
+          stderr.writeln('run:stderr: $line');
+        });
+      run.exitCode.then((int exitCode) { ok = false; });
+      await Future.any<dynamic>(<Future<dynamic>>[ ready.future, run.exitCode ]);
+      if (!ok)
+        throw 'Failed to run test app.';
+
+      final VMServiceClient client = new VMServiceClient.connect('ws://localhost:$kObservatoryPort/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');
+
+      print('reassembling app...');
+      final Future<VMExtensionEvent> frameFuture = frameEvents.first;
+      await isolate.invokeExtension('ext.flutter.reassemble');
+
+      // ensure we get an event
+      final VMExtensionEvent event = await frameFuture;
+      print('${event.kind}: ${event.data}');
+
+      // validate the fields
+      // {number: 8, startTime: 0, elapsed: 1437}
+      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);
+
+      run.stdin.write('q');
+      final int result = await run.exitCode;
+      if (result != 0)
+        throw 'Received unexpected exit code $result from run process.';
+    });
+    return new TaskResult.success(null);
+  });
+}
+
+void expect(bool value) {
+  if (!value)
+    throw 'failed assertion in service extensions test';
+}

dev/devicelab/manifest.yaml

@@ -121,6 +121,13 @@ tasks:
     required_agent_capabilities: ["has-android-device"]
     flaky: true
 
+  service_extensions_test:
+    description: >
+      Validates our service protocol extensions.
+    stage: devicelab
+    required_agent_capabilities: ["has-android-device"]
+    flaky: true
+
   android_sample_catalog_generator:
     description: >
       Builds sample catalog markdown pages and Android screenshots

packages/flutter/lib/foundation.dart

@@ -40,6 +40,7 @@ export 'src/foundation/licenses.dart';
 export 'src/foundation/observer_list.dart';
 export 'src/foundation/platform.dart';
 export 'src/foundation/print.dart';
+export 'src/foundation/profile.dart';
 export 'src/foundation/serialization.dart';
 export 'src/foundation/synchronous_future.dart';
 export 'src/foundation/tree_diagnostics_mixin.dart';

packages/flutter/lib/src/foundation/profile.dart

@@ -0,0 +1,18 @@
+// Copyright 2017 The Chromium 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 'dart:ui';
+
+/// Whether we've been built in release mode.
+const bool _kReleaseMode = const bool.fromEnvironment("dart.vm.product");
+
+/// When running in profile mode (or debug mode), invoke the given function.
+///
+/// In release mode, the function is not invoked.
+// TODO(devoncarew): Going forward, we'll want the call to profile() to be tree-shaken out.
+void profile(VoidCallback function) {
+  if (_kReleaseMode)
+    return;
+  function();
+}

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

@@ -4,7 +4,7 @@
 
 import 'dart:async';
 import 'dart:collection';
-import 'dart:developer';
+import 'dart:developer' as developer;
 import 'dart:ui' as ui show window;
 import 'dart:ui' show VoidCallback;
 
@@ -550,7 +550,8 @@ abstract class SchedulerBinding extends BindingBase {
   }
   Duration _currentFrameTimeStamp;
 
-  int _debugFrameNumber = 0;
+  int _profileFrameNumber = 0;
+  final Stopwatch _profileFrameStopwatch = new Stopwatch();
   String _debugBanner;
 
   /// Called by the engine to prepare the framework to produce a new frame.
@@ -577,22 +578,27 @@ abstract class SchedulerBinding extends BindingBase {
   /// statements printed during a frame from those printed between frames (e.g.
   /// in response to events or timers).
   void handleBeginFrame(Duration rawTimeStamp) {
-    Timeline.startSync('Frame');
+    developer.Timeline.startSync('Frame');
     _firstRawTimeStampInEpoch ??= rawTimeStamp;
     _currentFrameTimeStamp = _adjustForEpoch(rawTimeStamp ?? _lastRawTimeStamp);
     if (rawTimeStamp != null)
       _lastRawTimeStamp = rawTimeStamp;
 
+    profile(() {
+      _profileFrameNumber += 1;
+      _profileFrameStopwatch.reset();
+      _profileFrameStopwatch.start();
+    });
+
     assert(() {
-      _debugFrameNumber += 1;
       if (debugPrintBeginFrameBanner || debugPrintEndFrameBanner) {
         final StringBuffer frameTimeStampDescription = new StringBuffer();
         if (rawTimeStamp != null) {
           _debugDescribeTimeStamp(_currentFrameTimeStamp, frameTimeStampDescription);
         } else {
           frameTimeStampDescription.write('(warm-up frame)');
         }
-        _debugBanner = '▄▄▄▄▄▄▄▄ Frame ${_debugFrameNumber.toString().padRight(7)}   ${frameTimeStampDescription.toString().padLeft(18)} ▄▄▄▄▄▄▄▄';
+        _debugBanner = '▄▄▄▄▄▄▄▄ Frame ${_profileFrameNumber.toString().padRight(7)}   ${frameTimeStampDescription.toString().padLeft(18)} ▄▄▄▄▄▄▄▄';
         if (debugPrintBeginFrameBanner)
           debugPrint(_debugBanner);
       }
@@ -603,7 +609,7 @@ abstract class SchedulerBinding extends BindingBase {
     _hasScheduledFrame = false;
     try {
       // TRANSIENT FRAME CALLBACKS
-      Timeline.startSync('Animate');
+      developer.Timeline.startSync('Animate');
       _schedulerPhase = SchedulerPhase.transientCallbacks;
       final Map<int, _FrameCallbackEntry> callbacks = _transientCallbacks;
       _transientCallbacks = <int, _FrameCallbackEntry>{};
@@ -628,7 +634,7 @@ abstract class SchedulerBinding extends BindingBase {
   /// useful when working with frame callbacks.
   void handleDrawFrame() {
     assert(_schedulerPhase == SchedulerPhase.midFrameMicrotasks);
-    Timeline.finishSync(); // end the "Animate" phase
+    developer.Timeline.finishSync(); // end the "Animate" phase
     try {
       // PERSISTENT FRAME CALLBACKS
       _schedulerPhase = SchedulerPhase.persistentCallbacks;
@@ -644,14 +650,22 @@ abstract class SchedulerBinding extends BindingBase {
         _invokeFrameCallback(callback, _currentFrameTimeStamp);
     } finally {
       _schedulerPhase = SchedulerPhase.idle;
-      _currentFrameTimeStamp = null;
-      Timeline.finishSync();
+      developer.Timeline.finishSync(); // end the Frame
+      profile(() {
+        _profileFrameStopwatch.stop();
+        developer.postEvent('Flutter.Frame', <String, dynamic>{
+          'number': _profileFrameNumber,
+          'startTime': _currentFrameTimeStamp.inMicroseconds,
+          'elapsed': _profileFrameStopwatch.elapsedMicroseconds
+        });
+      });
       assert(() {
         if (debugPrintEndFrameBanner)
           debugPrint('▀' * _debugBanner.length);
         _debugBanner = null;
         return true;
       });
+      _currentFrameTimeStamp = null;
     }
 
     // All frame-related callbacks have been executed. Run lower-priority tasks.

packages/flutter/test/foundation/profile_test.dart

@@ -0,0 +1,18 @@
+// Copyright 2017 The Chromium 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 'package:flutter/foundation.dart';
+import 'package:test/test.dart';
+
+const bool isReleaseMode = const bool.fromEnvironment("dart.vm.product");
+
+void main() {
+  test("profile invokes its closure in debug or profile mode", () {
+    int count = 0;
+    profile(() {
+      count++;
+    });
+    expect(count, isReleaseMode ? 0 : 1);
+  });
+}