Record flutter run success/fail, build mode, platform, start time in analytics (#9597)

FlutterCommand.runCommand subclasses can optionally return a FlutterCommandResult which is used to append additional analytics. 

Fix flutter run timing report and add a bunch of dimensional data

packages/flutter_tools/lib/src/base/utils.dart

@@ -8,7 +8,9 @@ import 'dart:math' show Random;
 
 import 'package:crypto/crypto.dart';
 import 'package:intl/intl.dart';
+import 'package:quiver/time.dart';
 
+import 'context.dart';
 import 'file_system.dart';
 import 'platform.dart';
 
@@ -203,3 +205,5 @@ class Uuid {
   String _printDigits(int value, int count) =>
       value.toRadixString(16).padLeft(count, '0');
 }
+
+Clock get clock => context.putIfAbsent(Clock, () => const Clock());

packages/flutter_tools/lib/src/commands/run.dart

@@ -200,7 +200,7 @@ class RunCommand extends RunCommandBase {
   bool get stayResident => argResults['resident'];
 
   @override
-  Future<Null> verifyThenRunCommand() async {
+  Future<FlutterCommandResult> verifyThenRunCommand() async {
     commandValidator();
     devices = await findAllTargetDevices();
     if (devices == null)
@@ -225,7 +225,7 @@ class RunCommand extends RunCommandBase {
   }
 
   @override
-  Future<Null> runCommand() async {
+  Future<FlutterCommandResult> runCommand() async {
     Cache.releaseLockEarly();
 
     // Enable hot mode by default if `--no-hot` was not passed and we are in
@@ -250,10 +250,15 @@ class RunCommand extends RunCommandBase {
       } catch (error) {
         throwToolExit(error.toString());
       }
+      final DateTime appStartedTime = clock.now();
       final int result = await app.runner.waitForAppToFinish();
       if (result != 0)
         throwToolExit(null, exitCode: result);
-      return null;
+      return new FlutterCommandResult(
+        ExitStatus.success,
+        analyticsParameters: <String>['daemon'],
+        endTimeOverride: appStartedTime,
+      );
     }
 
     for (Device device in devices) {
@@ -303,11 +308,34 @@ class RunCommand extends RunCommandBase {
       );
     }
 
+    DateTime appStartedTime;
+    // Sync completer so the completing agent attaching to the resident doesn't 
+    // need to know about analytics. 
+    //
+    // Do not add more operations to the future.
+    final Completer<Null> appStartedTimeRecorder = new Completer<Null>.sync();
+    appStartedTimeRecorder.future.then(
+      (_) { appStartedTime = clock.now(); }
+    );
+
     final int result = await runner.run(
+      appStartedCompleter: appStartedTimeRecorder,
       route: route,
       shouldBuild: !runningWithPrebuiltApplication && argResults['build'],
     );
     if (result != 0)
       throwToolExit(null, exitCode: result);
+    return new FlutterCommandResult(
+      ExitStatus.success,
+      analyticsParameters: <String>[
+        hotMode ? 'hot' : 'cold',
+        getModeName(getBuildMode()),
+        devices.length == 1 
+            ? getNameForTargetPlatform(await devices[0].targetPlatform)
+            : 'multiple',
+        devices.length == 1 && await devices[0].isLocalEmulator ? 'emulator' : null
+      ],
+      endTimeOverride: appStartedTime,
+    );
   }
 }

packages/flutter_tools/lib/src/runner/flutter_command.dart

@@ -6,10 +6,12 @@ import 'dart:async';
 
 import 'package:args/command_runner.dart';
 import 'package:meta/meta.dart';
+import 'package:quiver/strings.dart';
 
 import '../application_package.dart';
 import '../base/common.dart';
 import '../base/file_system.dart';
+import '../base/utils.dart';
 import '../build_info.dart';
 import '../dart/package_map.dart';
 import '../dart/pub.dart';
@@ -22,6 +24,40 @@ import 'flutter_command_runner.dart';
 
 typedef void Validator();
 
+enum ExitStatus {
+  success,
+  warning,
+  fail,
+}
+
+/// [FlutterCommand]s' subclasses' [FlutterCommand.runCommand] can optionally
+/// provide a [FlutterCommandResult] to furnish additional information for 
+/// analytics.
+class FlutterCommandResult {
+  FlutterCommandResult(
+    this.exitStatus, {
+    this.analyticsParameters,
+    this.endTimeOverride,
+  }) { 
+    assert(exitStatus != null); 
+  }
+
+  final ExitStatus exitStatus;
+
+  /// Optional dimension data that can be appended to the timing event.
+  /// https://developers.google.com/analytics/devguides/collection/analyticsjs/field-reference#timingLabel
+  /// Do not add PII.
+  final List<String> analyticsParameters;
+
+  /// Optional epoch time when the command's non-interactive wait time is 
+  /// complete during the command's execution. Use to measure user perceivable
+  /// latency without measuring user interaction time. 
+  /// 
+  /// [FlutterCommand] will automatically measure and report the command's
+  /// complete time if not overriden.
+  final DateTime endTimeOverride;
+}
+
 abstract class FlutterCommand extends Command<Null> {
   FlutterCommand() {
     commandValidator = commonCommandValidator;
@@ -111,18 +147,37 @@ abstract class FlutterCommand extends Command<Null> {
   /// and [runCommand] to execute the command
   /// so that this method can record and report the overall time to analytics.
   @override
-  Future<Null> run() {
-    final Stopwatch stopwatch = new Stopwatch()..start();
-    final UsageTimer analyticsTimer = usagePath == null ? null : flutterUsage.startTimer(name);
+  Future<Null> run() async {
+    final DateTime startTime = clock.now();
 
     if (flutterUsage.isFirstRun)
       flutterUsage.printWelcome();
 
-    return verifyThenRunCommand().whenComplete(() {
-      final int ms = stopwatch.elapsedMilliseconds;
-      printTrace("'flutter $name' took ${ms}ms.");
-      analyticsTimer?.finish();
-    });
+    final FlutterCommandResult commandResult = await verifyThenRunCommand();
+
+    final DateTime endTime = clock.now();
+    printTrace("'flutter $name' took ${getElapsedAsMilliseconds(endTime.difference(startTime))}.");
+    if (usagePath != null) {
+      final List<String> labels = <String>[];
+      if (commandResult?.exitStatus != null)
+        labels.add(getEnumName(commandResult.exitStatus));
+      if (commandResult?.analyticsParameters?.isNotEmpty ?? false)
+        labels.addAll(commandResult.analyticsParameters);
+
+      final String label = labels
+          .where((String label) => !isBlank(label))
+          .join('-');
+      flutterUsage.sendTiming(
+        'flutter', 
+        name, 
+        // If the command provides its own end time, use it. Otherwise report
+        // the duration of the entire execution.
+        (commandResult?.endTimeOverride ?? endTime).difference(startTime), 
+        // Report in the form of `success-[parameter1-parameter2]`, all of which
+        // can be null if the command doesn't provide a FlutterCommandResult.
+        label: label == '' ? null : label,
+      );
+    }
   }
 
   /// Perform validation then call [runCommand] to execute the command.
@@ -133,7 +188,7 @@ abstract class FlutterCommand extends Command<Null> {
   /// then call this method to execute the command
   /// rather than calling [runCommand] directly.
   @mustCallSuper
-  Future<Null> verifyThenRunCommand() async {
+  Future<FlutterCommandResult> verifyThenRunCommand() async {
     // Populate the cache. We call this before pub get below so that the sky_engine
     // package is available in the flutter cache for pub to find.
     if (shouldUpdateCache)
@@ -147,12 +202,13 @@ abstract class FlutterCommand extends Command<Null> {
     final String commandPath = await usagePath;
     if (commandPath != null)
       flutterUsage.sendCommand(commandPath);
-
-    await runCommand();
+    return runCommand();
   }
 
   /// Subclasses must implement this to execute the command.
-  Future<Null> runCommand();
+  /// Optionally provide a [FlutterCommandResult] to send more details about the 
+  /// execution for analytics.
+  Future<FlutterCommandResult> runCommand();
 
   /// Find and return all target [Device]s based upon currently connected
   /// devices and criteria entered by the user on the command line.

packages/flutter_tools/lib/src/usage.dart

@@ -81,15 +81,20 @@ class Usage {
       _analytics.sendEvent(category, parameter);
   }
 
-  void sendTiming(String category, String variableName, Duration duration) {
-    _analytics.sendTiming(variableName, duration.inMilliseconds, category: category);
-  }
-
-  UsageTimer startTimer(String event) {
-    if (suppressAnalytics)
-      return new _MockUsageTimer();
-    else
-      return new UsageTimer._(event, _analytics.startTimer(event, category: 'flutter'));
+  void sendTiming(
+    String category, 
+    String variableName, 
+    Duration duration, {
+    String label,
+    }) {
+    if (!suppressAnalytics) {
+      _analytics.sendTiming(
+        variableName, 
+        duration.inMilliseconds, 
+        category: category,
+        label: label,
+      );
+    }
   }
 
   void sendException(dynamic exception, StackTrace trace) {
@@ -138,24 +143,3 @@ class Usage {
   ''', emphasis: true);
   }
 }
-
-class UsageTimer {
-  UsageTimer._(this.event, this._timer);
-
-  final String event;
-  final AnalyticsTimer _timer;
-
-  void finish() {
-    _timer.finish();
-  }
-}
-
-class _MockUsageTimer implements UsageTimer {
-  @override
-  String event;
-  @override
-  AnalyticsTimer _timer;
-
-  @override
-  void finish() { }
-}

packages/flutter_tools/test/analytics_test.dart

@@ -9,6 +9,8 @@ import 'package:flutter_tools/src/commands/create.dart';
 import 'package:flutter_tools/src/commands/config.dart';
 import 'package:flutter_tools/src/commands/doctor.dart';
 import 'package:flutter_tools/src/usage.dart';
+import 'package:mockito/mockito.dart';
+import 'package:quiver/time.dart';
 import 'package:test/test.dart';
 
 import 'src/common.dart';
@@ -75,6 +77,38 @@ void main() {
     });
   });
 
+  group('analytics with mocks', () {
+    Usage mockUsage;
+    Clock mockClock;
+    List<int> mockTimes;
+
+    setUp(() {
+      mockUsage = new MockUsage();
+      when(mockUsage.isFirstRun).thenReturn(false);
+      mockClock = new MockClock();
+      when(mockClock.now()).thenAnswer(
+        (Invocation _) => new DateTime.fromMillisecondsSinceEpoch(mockTimes.removeAt(0))
+      );
+    });
+
+    testUsingContext('flutter commands send timing events', () async {
+      mockTimes = <int>[1000, 2000];
+      final DoctorCommand command = new DoctorCommand();
+      final CommandRunner<Null> runner = createTestCommandRunner(command);
+      await runner.run(<String>['doctor']);
+
+      verify(mockClock.now()).called(2);
+
+      expect(
+        verify(mockUsage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured, 
+        <dynamic>['flutter', 'doctor', const Duration(milliseconds: 1000), null]
+      );
+    }, overrides: <Type, Generator>{
+      Clock: () => mockClock,
+      Usage: () => mockUsage,
+    });
+  });
+
   group('analytics bots', () {
     testUsingContext('don\'t send on bots', () async {
       int count = 0;
@@ -90,3 +124,5 @@ void main() {
     });
   });
 }
+
+class MockUsage extends Mock implements Usage {}

packages/flutter_tools/test/src/context.dart

@@ -23,6 +23,7 @@ import 'package:flutter_tools/src/usage.dart';
 import 'package:flutter_tools/src/version.dart';
 import 'package:mockito/mockito.dart';
 import 'package:process/process.dart';
+import 'package:quiver/time.dart';
 import 'package:test/test.dart';
 
 import 'common.dart';
@@ -55,7 +56,8 @@ void _defaultInitializeContext(AppContext testContext) {
     })
     ..putIfAbsent(SimControl, () => new MockSimControl())
     ..putIfAbsent(Usage, () => new MockUsage())
-    ..putIfAbsent(FlutterVersion, () => new MockFlutterVersion());
+    ..putIfAbsent(FlutterVersion, () => new MockFlutterVersion())
+    ..putIfAbsent(Clock, () => const Clock());
 }
 
 void testUsingContext(String description, dynamic testMethod(), {
@@ -220,10 +222,7 @@ class MockUsage implements Usage {
   void sendEvent(String category, String parameter) { }
 
   @override
-  void sendTiming(String category, String variableName, Duration duration) { }
-
-  @override
-  UsageTimer startTimer(String event) => new _MockUsageTimer(event);
+  void sendTiming(String category, String variableName, Duration duration, { String label }) { }
 
   @override
   void sendException(dynamic exception, StackTrace trace) { }
@@ -238,14 +237,6 @@ class MockUsage implements Usage {
   void printWelcome() { }
 }
 
-class _MockUsageTimer implements UsageTimer {
-  _MockUsageTimer(this.event);
-
-  @override
-  final String event;
-
-  @override
-  void finish() { }
-}
-
 class MockFlutterVersion extends Mock implements FlutterVersion {}
+
+class MockClock extends Mock implements Clock {}

packages/flutter_tools/test/src/runner/flutter_command_test.dart

@@ -5,8 +5,10 @@
 import 'dart:async';
 
 import 'package:flutter_tools/src/cache.dart';
+import 'package:flutter_tools/src/usage.dart';
 import 'package:flutter_tools/src/runner/flutter_command.dart';
 import 'package:mockito/mockito.dart';
+import 'package:quiver/time.dart';
 import 'package:test/test.dart';
 
 import '../context.dart';
@@ -16,9 +18,18 @@ void main() {
   group('Flutter Command', () {
 
     MockCache cache;
+    MockClock clock;
+    MockUsage usage;
+    List<int> mockTimes;
 
     setUp(() {
       cache = new MockCache();
+      clock = new MockClock();
+      usage = new MockUsage();
+      when(usage.isFirstRun).thenReturn(false);
+      when(clock.now()).thenAnswer(
+        (Invocation _) => new DateTime.fromMillisecondsSinceEpoch(mockTimes.removeAt(0))
+      );
     });
 
     testUsingContext('honors shouldUpdateCache false', () async {
@@ -38,12 +49,84 @@ void main() {
     overrides: <Type, Generator>{
       Cache: () => cache,
     });
+
+    testUsingContext('report execution timing by default', () async {
+      // Crash if called a third time which is unexpected.
+      mockTimes = <int>[1000, 2000];
+
+      final DummyFlutterCommand flutterCommand = new DummyFlutterCommand();
+      await flutterCommand.run();
+      verify(clock.now()).called(2);
+
+      expect(
+        verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured, 
+        <dynamic>['flutter', 'dummy', const Duration(milliseconds: 1000), null]
+      );
+    },
+    overrides: <Type, Generator>{
+      Clock: () => clock,
+      Usage: () => usage,
+    });
+
+    testUsingContext('no timing report without usagePath', () async {
+      // Crash if called a third time which is unexpected.
+      mockTimes = <int>[1000, 2000];
+
+      final DummyFlutterCommand flutterCommand = 
+          new DummyFlutterCommand(noUsagePath: true);
+      await flutterCommand.run();
+      verify(clock.now()).called(2);
+      verifyNever(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny));
+    },
+    overrides: <Type, Generator>{
+      Clock: () => clock,
+      Usage: () => usage,
+    });
+    
+    testUsingContext('report additional FlutterCommandResult data', () async {
+      // Crash if called a third time which is unexpected.
+      mockTimes = <int>[1000, 2000];
+
+      final FlutterCommandResult commandResult = new FlutterCommandResult(
+        ExitStatus.fail,
+        // nulls should be cleaned up.
+        analyticsParameters: <String> ['blah1', 'blah2', null, 'blah3'],
+        endTimeOverride: new DateTime.fromMillisecondsSinceEpoch(1500)
+      );
+
+      final DummyFlutterCommand flutterCommand = 
+          new DummyFlutterCommand(flutterCommandResult: commandResult);
+      await flutterCommand.run();
+      verify(clock.now()).called(2);
+      expect(
+        verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured, 
+        <dynamic>[
+          'flutter', 
+          'dummy', 
+          const Duration(milliseconds: 500), // FlutterCommandResult's end time used instead.
+          'fail-blah1-blah2-blah3',
+        ],
+      );    
+    },
+    overrides: <Type, Generator>{
+      Clock: () => clock,
+      Usage: () => usage,
+    });
+
   });
+
 }
 
 class DummyFlutterCommand extends FlutterCommand {
 
-  DummyFlutterCommand({this.shouldUpdateCache});
+  DummyFlutterCommand({
+    this.shouldUpdateCache : false, 
+    this.noUsagePath : false, 
+    this.flutterCommandResult
+  });
+
+  final bool noUsagePath;
+  final FlutterCommandResult flutterCommandResult;
 
   @override
   final bool shouldUpdateCache;
@@ -51,13 +134,18 @@ class DummyFlutterCommand extends FlutterCommand {
   @override
   String get description => 'does nothing';
 
+  @override
+  Future<String> get usagePath => noUsagePath ? null : super.usagePath;
+
   @override
   String get name => 'dummy';
 
   @override
-  Future<Null> runCommand() async {
-    // does nothing.
+  Future<FlutterCommandResult> runCommand() async {
+    return flutterCommandResult;
   }
 }
 
-class MockCache extends Mock implements Cache {}
+class MockCache extends Mock implements Cache {}
+
+class MockUsage extends Mock implements Usage {}