Instrument vm service extensions in the gallery (#17977)

https://github.com/flutter/flutter/issues/17956

* Add a `debugInstrumentAction()` method that will wrap an action
  in a stopwatch and print the time it took to run the action.
* Add a global `debugInstrumentationEnabled` that will control
  whether `debugInstrumentAction()` does anything (even in debug
  builds).
* Add some basic instrumentation to `registerServiceExtension()`
* Temporarily enable the `debugInstrumentationEnabled` flag in the
  Gallery to give us better visibility into what's happening in
  https://github.com/flutter/flutter/issues/17956

examples/flutter_gallery/lib/main.dart

@@ -5,11 +5,15 @@
 // Thanks for checking out Flutter!
 // Like what you see? Tweet us @flutterio
 
+import 'package:flutter/foundation.dart';
 import 'package:flutter/material.dart';
 
 import 'gallery/app.dart';
 
 void main() {
+  // Temporary debugging hook for https://github.com/flutter/flutter/issues/17956
+  debugInstrumentationEnabled = true;
+
   // Overriding https://github.com/flutter/flutter/issues/13736 for better
   // visual effect at the cost of performance.
   MaterialPageRoute.debugEnableFadingRoutes = true; // ignore: deprecated_member_use

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

@@ -11,7 +11,9 @@ import 'package:meta/meta.dart';
 
 import 'assertions.dart';
 import 'basic_types.dart';
+import 'debug.dart';
 import 'platform.dart';
+import 'print.dart';
 
 /// Signature for service extensions.
 ///
@@ -363,6 +365,11 @@ abstract class BindingBase {
     final String methodName = 'ext.flutter.$name';
     developer.registerExtension(methodName, (String method, Map<String, String> parameters) async {
       assert(method == methodName);
+      assert(() {
+        if (debugInstrumentationEnabled)
+          debugPrint('service extension method received: $method($parameters)');
+        return true;
+      }());
 
       // VM service extensions are handled as "out of band" messages by the VM,
       // which means they are handled at various times, generally ASAP.
@@ -374,7 +381,9 @@ abstract class BindingBase {
       // the possibility that they're handled in the middle of a frame, which
       // breaks many assertions. As such, we ensure they we run the callbacks
       // on the outer event loop here.
-      await new Future<void>.delayed(Duration.zero);
+      await debugInstrumentAction<void>('Wait for outer event loop', () {
+        return new Future<void>.delayed(Duration.zero);
+      });
 
       dynamic caughtException;
       StackTrace caughtStack;

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

@@ -2,6 +2,8 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+import 'dart:async';
+
 import 'assertions.dart';
 import 'platform.dart';
 import 'print.dart';
@@ -29,6 +31,51 @@ bool debugAssertAllFoundationVarsUnset(String reason, { DebugPrintCallback debug
   return true;
 }
 
+/// Boolean value indicating whether [debugInstrumentAction] will instrument
+/// actions in debug builds.
+bool debugInstrumentationEnabled = false;
+
+/// Runs the specified [action], timing how long the action takes in debug
+/// builds when [debugInstrumentationEnabled] is true.
+///
+/// The instrumentation will be printed to the logs using [debugPrint]. In
+/// non-debug builds, or when [debugInstrumentationEnabled] is false, this will
+/// run [action] without any instrumentation.
+///
+/// Returns the result of running [action], wrapped in a `Future` if the action
+/// was synchronous.
+Future<T> debugInstrumentAction<T>(String description, FutureOr<T> action()) {
+  if (!debugInstrumentationEnabled)
+    return new Future<T>.value(action());
+
+  Stopwatch stopwatch;
+  assert(() {
+    stopwatch = new Stopwatch()..start();
+    return true;
+  } ());
+  void stopStopwatchAndPrintElapsed() {
+    assert(() {
+      stopwatch.stop();
+      debugPrint('Action "$description" took ${stopwatch.elapsed}');
+      return true;
+    }());
+  }
+
+  Future<T> returnResult;
+  FutureOr<T> actionResult;
+  try {
+    actionResult = action();
+  } finally {
+    if (actionResult is Future<T>) {
+      returnResult = actionResult.whenComplete(stopStopwatchAndPrintElapsed);
+    } else {
+      stopStopwatchAndPrintElapsed();
+      returnResult = new Future<T>.value(actionResult);
+    }
+  }
+  return returnResult;
+}
+
 /// Arguments to whitelist [Timeline] events in order to be shown in the
 /// developer centric version of the Observatory Timeline.
 const Map<String, String> timelineWhitelistArguments = const <String, String>{

packages/flutter/test/foundation/debug_test.dart

@@ -0,0 +1,74 @@
+// 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:flutter_test/flutter_test.dart';
+
+void main() {
+  group('debugInstrumentAction', () {
+    DebugPrintCallback originalDebugPrintCallback;
+    StringBuffer printBuffer;
+
+    setUp(() {
+      debugInstrumentationEnabled = true;
+      printBuffer = new StringBuffer();
+      originalDebugPrintCallback = debugPrint;
+      debugPrint = (String message, {int wrapWidth}) {
+        printBuffer.writeln(message);
+      };
+    });
+
+    tearDown(() {
+      debugInstrumentationEnabled = false;
+      debugPrint = originalDebugPrintCallback;
+    });
+
+    test('works with sync actions', () async {
+      final int result = await debugInstrumentAction<int>('no-op', () {
+        debugPrint('action()');
+        return 1;
+      });
+      expect(result, 1);
+      expect(
+        printBuffer.toString(),
+        matches(new RegExp('^action\\(\\)\nAction "no-op" took .+\$', multiLine: true)),
+      );
+    });
+
+    test('works with async actions', () async {
+      final int result = await debugInstrumentAction<int>('no-op', () async {
+        debugPrint('action()');
+        return 1;
+      });
+      expect(result, 1);
+      expect(
+        printBuffer.toString(),
+        matches(new RegExp('^action\\(\\)\nAction "no-op" took .+\$', multiLine: true)),
+      );
+    });
+
+    test('throws if sync action throws', () {
+      try {
+        debugInstrumentAction<void>('throws', () => throw 'Error');
+        fail('Error expected but not thrown');
+      } on String catch (error) {
+        expect(error, 'Error');
+        expect(printBuffer.toString(), matches(r'^Action "throws" took .+'));
+      }
+    });
+
+    test('returns failing future if async action throws', () async {
+      try {
+        await debugInstrumentAction<void>('throws', () async {
+          await new Future<void>.delayed(Duration.zero);
+          throw 'Error';
+        });
+        fail('Error expected but not thrown');
+      } on String catch (error) {
+        expect(error, 'Error');
+        expect(printBuffer.toString(), matches(r'^Action "throws" took .+'));
+      }
+    });
+  });
+}