Add more analytics for hot reload in flutter_tools. (#83972)

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

@@ -19,7 +19,10 @@ class StopwatchFactory {
   const StopwatchFactory();
 
   /// Create a new [Stopwatch] instance.
-  Stopwatch createStopwatch() => Stopwatch();
+  ///
+  /// The optional [name] parameter is useful in tests when there are multiple
+  /// instances being created.
+  Stopwatch createStopwatch([String name = '']) => Stopwatch();
 }
 
 typedef VoidCallback = void Function();

packages/flutter_tools/lib/src/devfs.dart

@@ -399,18 +399,34 @@ class UpdateFSReport {
     int invalidatedSourcesCount = 0,
     int syncedBytes = 0,
     this.fastReassembleClassName,
+    int scannedSourcesCount = 0,
+    Duration compileDuration = Duration.zero,
+    Duration transferDuration = Duration.zero,
+    Duration findInvalidatedDuration = Duration.zero,
   }) : _success = success,
        _invalidatedSourcesCount = invalidatedSourcesCount,
-       _syncedBytes = syncedBytes;
+       _syncedBytes = syncedBytes,
+       _scannedSourcesCount = scannedSourcesCount,
+       _compileDuration = compileDuration,
+       _transferDuration = transferDuration,
+       _findInvalidatedDuration = findInvalidatedDuration;
 
   bool get success => _success;
   int get invalidatedSourcesCount => _invalidatedSourcesCount;
   int get syncedBytes => _syncedBytes;
+  int get scannedSourcesCount => _scannedSourcesCount;
+  Duration get compileDuration => _compileDuration;
+  Duration get transferDuration => _transferDuration;
+  Duration get findInvalidatedDuration => _findInvalidatedDuration;
 
   bool _success;
   String fastReassembleClassName;
   int _invalidatedSourcesCount;
   int _syncedBytes;
+  int _scannedSourcesCount;
+  Duration _compileDuration;
+  Duration _transferDuration;
+  Duration _findInvalidatedDuration;
 
   void incorporateResults(UpdateFSReport report) {
     if (!report._success) {
@@ -419,6 +435,10 @@ class UpdateFSReport {
     fastReassembleClassName ??= report.fastReassembleClassName;
     _invalidatedSourcesCount += report._invalidatedSourcesCount;
     _syncedBytes += report._syncedBytes;
+    _scannedSourcesCount += report._scannedSourcesCount;
+    _compileDuration += report._compileDuration;
+    _transferDuration += report._transferDuration;
+    _findInvalidatedDuration += report._findInvalidatedDuration;
   }
 }
 
@@ -435,6 +455,7 @@ class DevFS {
     @required FileSystem fileSystem,
     HttpClient httpClient,
     Duration uploadRetryThrottle,
+    StopwatchFactory stopwatchFactory = const StopwatchFactory(),
   }) : _vmService = serviceProtocol,
        _logger = logger,
        _fileSystem = fileSystem,
@@ -446,13 +467,14 @@ class DevFS {
         uploadRetryThrottle: uploadRetryThrottle,
         httpClient: httpClient ?? ((context.get<HttpClientFactory>() == null)
           ? HttpClient()
-          : context.get<HttpClientFactory>()())
-      );
+          : context.get<HttpClientFactory>()())),
+       _stopwatchFactory = stopwatchFactory;
 
   final FlutterVmService _vmService;
   final _DevFSHttpWriter _httpWriter;
   final Logger _logger;
   final FileSystem _fileSystem;
+  final StopwatchFactory _stopwatchFactory;
 
   final String fsName;
   final Directory rootDirectory;
@@ -575,6 +597,7 @@ class DevFS {
 
     // Await the compiler response after checking if the bundle is updated. This allows the file
     // stating to be done while waiting for the frontend_server response.
+    final Stopwatch compileTimer = _stopwatchFactory.createStopwatch('compile')..start();
     final Future<CompilerOutput> pendingCompilerOutput = generator.recompile(
       mainUri,
       invalidatedFiles,
@@ -582,7 +605,11 @@ class DevFS {
       fs: _fileSystem,
       projectRootPath: projectRootPath,
       packageConfig: packageConfig,
-    );
+    ).then((CompilerOutput result) {
+      compileTimer.stop();
+      return result;
+    });
+
     if (bundle != null) {
       // The tool writes the assets into the AssetBundle working dir so that they
       // are in the same location in DevFS and the iOS simulator.
@@ -627,15 +654,19 @@ class DevFS {
       }
     }
     _logger.printTrace('Updating files.');
+    final Stopwatch transferTimer = _stopwatchFactory.createStopwatch('transfer')..start();
     if (dirtyEntries.isNotEmpty) {
       await (devFSWriter ?? _httpWriter).write(dirtyEntries, _baseUri, _httpWriter);
     }
+    transferTimer.stop();
     _logger.printTrace('DevFS: Sync finished');
     return UpdateFSReport(
       success: true,
       syncedBytes: syncedBytes,
       invalidatedSourcesCount: invalidatedFiles.length,
       fastReassembleClassName: _checkIfSingleWidgetReloadApplied(),
+      compileDuration: compileTimer.elapsed,
+      transferDuration: transferTimer.elapsed,
     );
   }
 

packages/flutter_tools/lib/src/reporting/custom_dimensions.dart

@@ -61,6 +61,11 @@ class CustomDimensions {
     this.fastReassemble,
     this.nullSafeMigratedLibraries,
     this.nullSafeTotalLibraries,
+    this.hotEventCompileTimeInMs,
+    this.hotEventFindInvalidatedTimeInMs,
+    this.hotEventScannedSourcesCount,
+    this.hotEventReassembleTimeInMs,
+    this.hotEventReloadVMTimeInMs,
   });
 
   final String? sessionHostOsDetails;  // cd1
@@ -113,6 +118,11 @@ class CustomDimensions {
   final bool? fastReassemble;  // cd48
   final int? nullSafeMigratedLibraries;  // cd49
   final int? nullSafeTotalLibraries;  // cd50
+  final int? hotEventCompileTimeInMs;  // cd 51
+  final int? hotEventFindInvalidatedTimeInMs;  // cd 52
+  final int? hotEventScannedSourcesCount;  // cd 53
+  final int? hotEventReassembleTimeInMs;  // cd 54
+  final int? hotEventReloadVMTimeInMs;  // cd 55
 
   /// Convert to a map that will be used to upload to the analytics backend.
   Map<String, String> toMap() => <String, String>{
@@ -166,6 +176,11 @@ class CustomDimensions {
       if (fastReassemble != null) cdKey(CustomDimensionsEnum.fastReassemble): fastReassemble.toString(),
       if (nullSafeMigratedLibraries != null) cdKey(CustomDimensionsEnum.nullSafeMigratedLibraries): nullSafeMigratedLibraries.toString(),
       if (nullSafeTotalLibraries != null) cdKey(CustomDimensionsEnum.nullSafeTotalLibraries): nullSafeTotalLibraries.toString(),
+      if (hotEventCompileTimeInMs != null) cdKey(CustomDimensionsEnum.hotEventCompileTimeInMs): hotEventCompileTimeInMs.toString(),
+      if (hotEventFindInvalidatedTimeInMs != null) cdKey(CustomDimensionsEnum.hotEventFindInvalidatedTimeInMs): hotEventFindInvalidatedTimeInMs.toString(),
+      if (hotEventScannedSourcesCount != null) cdKey(CustomDimensionsEnum.hotEventScannedSourcesCount): hotEventScannedSourcesCount.toString(),
+      if (hotEventReassembleTimeInMs != null) cdKey(CustomDimensionsEnum.hotEventReassembleTimeInMs): hotEventReassembleTimeInMs.toString(),
+      if (hotEventReloadVMTimeInMs != null) cdKey(CustomDimensionsEnum.hotEventReloadVMTimeInMs): hotEventReloadVMTimeInMs.toString(),
     };
 
   /// Merge the values of two [CustomDimensions] into one. If a value is defined
@@ -226,6 +241,11 @@ class CustomDimensions {
       fastReassemble: other.fastReassemble ?? fastReassemble,
       nullSafeMigratedLibraries: other.nullSafeMigratedLibraries ?? nullSafeMigratedLibraries,
       nullSafeTotalLibraries: other.nullSafeTotalLibraries ?? nullSafeTotalLibraries,
+      hotEventCompileTimeInMs: other.hotEventCompileTimeInMs ?? hotEventCompileTimeInMs,
+      hotEventFindInvalidatedTimeInMs: other.hotEventFindInvalidatedTimeInMs ?? hotEventFindInvalidatedTimeInMs,
+      hotEventScannedSourcesCount: other.hotEventScannedSourcesCount ?? hotEventScannedSourcesCount,
+      hotEventReassembleTimeInMs: other.hotEventReassembleTimeInMs ?? hotEventReassembleTimeInMs,
+      hotEventReloadVMTimeInMs: other.hotEventReloadVMTimeInMs ?? hotEventReloadVMTimeInMs,
     );
   }
 
@@ -280,6 +300,11 @@ class CustomDimensions {
       fastReassemble: _extractBool(map, CustomDimensionsEnum.fastReassemble),
       nullSafeMigratedLibraries: _extractInt(map, CustomDimensionsEnum.nullSafeMigratedLibraries),
       nullSafeTotalLibraries: _extractInt(map, CustomDimensionsEnum.nullSafeTotalLibraries),
+      hotEventCompileTimeInMs: _extractInt(map, CustomDimensionsEnum.hotEventCompileTimeInMs),
+      hotEventFindInvalidatedTimeInMs: _extractInt(map, CustomDimensionsEnum.hotEventFindInvalidatedTimeInMs),
+      hotEventScannedSourcesCount: _extractInt(map, CustomDimensionsEnum.hotEventScannedSourcesCount),
+      hotEventReassembleTimeInMs: _extractInt(map, CustomDimensionsEnum.hotEventReassembleTimeInMs),
+      hotEventReloadVMTimeInMs: _extractInt(map, CustomDimensionsEnum.hotEventReloadVMTimeInMs),
     );
 
   static bool? _extractBool(Map<String, String> map, CustomDimensionsEnum field) =>
@@ -365,6 +390,11 @@ enum CustomDimensionsEnum {
   fastReassemble,  // cd48
   nullSafeMigratedLibraries,  // cd49
   nullSafeTotalLibraries,  // cd50
+  hotEventCompileTimeInMs,  // cd51
+  hotEventFindInvalidatedTimeInMs,  // cd52
+  hotEventScannedSourcesCount,  // cd53
+  hotEventReassembleTimeInMs,  // cd54
+  hotEventReloadVMTimeInMs,  // cd55
 }
 
 String cdKey(CustomDimensionsEnum cd) => 'cd${cd.index + 1}';

packages/flutter_tools/lib/src/reporting/events.dart

@@ -49,6 +49,11 @@ class HotEvent extends UsageEvent {
     this.invalidatedSourcesCount,
     this.transferTimeInMs,
     this.overallTimeInMs,
+    this.compileTimeInMs,
+    this.findInvalidatedTimeInMs,
+    this.scannedSourcesCount,
+    this.reassembleTimeInMs,
+    this.reloadVMTimeInMs,
   }) : super('hot', parameter, flutterUsage: globals.flutterUsage);
 
   final String? reason;
@@ -65,6 +70,11 @@ class HotEvent extends UsageEvent {
   final int? invalidatedSourcesCount;
   final int? transferTimeInMs;
   final int? overallTimeInMs;
+  final int? compileTimeInMs;
+  final int? findInvalidatedTimeInMs;
+  final int? scannedSourcesCount;
+  final int? reassembleTimeInMs;
+  final int? reloadVMTimeInMs;
 
   @override
   void send() {
@@ -83,6 +93,11 @@ class HotEvent extends UsageEvent {
       hotEventTransferTimeInMs: transferTimeInMs,
       hotEventOverallTimeInMs: overallTimeInMs,
       fastReassemble: fastReassemble,
+      hotEventCompileTimeInMs: compileTimeInMs,
+      hotEventFindInvalidatedTimeInMs: findInvalidatedTimeInMs,
+      hotEventScannedSourcesCount: scannedSourcesCount,
+      hotEventReassembleTimeInMs: reassembleTimeInMs,
+      hotEventReloadVMTimeInMs: reloadVMTimeInMs,
     );
     flutterUsage.sendEvent(category, parameter, parameters: parameters);
   }

packages/flutter_tools/lib/src/resident_runner.dart

@@ -1460,7 +1460,7 @@ abstract class ResidentRunner extends ResidentHandlers {
 }
 
 class OperationResult {
-  OperationResult(this.code, this.message, { this.fatal = false });
+  OperationResult(this.code, this.message, { this.fatal = false, this.updateFSReport });
 
   /// The result of the operation; a non-zero code indicates a failure.
   final int code;
@@ -1471,6 +1471,8 @@ class OperationResult {
   /// Whether this error should cause the runner to exit.
   final bool fatal;
 
+  final UpdateFSReport updateFSReport;
+
   bool get isOk => code == 0;
 
   static final OperationResult ok = OperationResult(0, '');

packages/flutter_tools/test/general.shard/base/logger_test.dart

@@ -244,7 +244,7 @@ void main() {
       );
       final VerboseLogger verboseLogger = VerboseLogger(
         mockLogger,
-        stopwatchFactory: FakeStopwatchFactory(fakeStopWatch),
+        stopwatchFactory: FakeStopwatchFactory(stopwatch: fakeStopWatch),
       );
 
       verboseLogger.printStatus('Hey Hey Hey Hey');
@@ -266,7 +266,7 @@ void main() {
         outputPreferences: OutputPreferences.test(showColor: true),
       );
       final VerboseLogger verboseLogger = VerboseLogger(
-        mockLogger, stopwatchFactory: FakeStopwatchFactory(fakeStopWatch),
+        mockLogger, stopwatchFactory: FakeStopwatchFactory(stopwatch: fakeStopWatch),
       );
 
       verboseLogger.printStatus('Hey Hey Hey Hey');
@@ -377,7 +377,7 @@ void main() {
       mockStopwatch = FakeStopwatch();
       mockStdio = FakeStdio();
       called = 0;
-      stopwatchFactory = FakeStopwatchFactory(mockStopwatch);
+      stopwatchFactory = FakeStopwatchFactory(stopwatch: mockStopwatch);
     });
 
     List<String> outputStdout() => mockStdio.writtenToStdout.join('').split('\n');
@@ -938,7 +938,7 @@ void main() {
         ),
         stdio: fakeStdio,
         outputPreferences: OutputPreferences.test(showColor: false),
-        stopwatchFactory: FakeStopwatchFactory(fakeStopwatch),
+        stopwatchFactory: FakeStopwatchFactory(stopwatch: fakeStopwatch),
       );
       final Status status = logger.startProgress(
         'Hello',
@@ -1062,53 +1062,6 @@ void main() {
   });
 }
 
-class FakeStopwatch implements Stopwatch {
-  @override
-  bool get isRunning => _isRunning;
-  bool _isRunning = false;
-
-  @override
-  void start() => _isRunning = true;
-
-  @override
-  void stop() => _isRunning = false;
-
-  @override
-  Duration elapsed = Duration.zero;
-
-  @override
-  int get elapsedMicroseconds => elapsed.inMicroseconds;
-
-  @override
-  int get elapsedMilliseconds => elapsed.inMilliseconds;
-
-  @override
-  int get elapsedTicks => elapsed.inMilliseconds;
-
-  @override
-  int get frequency => 1000;
-
-  @override
-  void reset() {
-    _isRunning = false;
-    elapsed = Duration.zero;
-  }
-
-  @override
-  String toString() => '$runtimeType $elapsed $isRunning';
-}
-
-class FakeStopwatchFactory implements StopwatchFactory {
-  FakeStopwatchFactory([this.stopwatch]);
-
-  Stopwatch stopwatch;
-
-  @override
-  Stopwatch createStopwatch() {
-    return stopwatch ?? FakeStopwatch();
-  }
-}
-
 /// A fake [Logger] that throws the [Invocation] for any method call.
 class FakeLogger implements Logger {
   @override

packages/flutter_tools/test/general.shard/devfs_test.dart

@@ -425,6 +425,51 @@ void main() {
       Uri.parse('goodbye'): DevFSFileContent(file),
     }, Uri.parse('/foo/bar/devfs/')), throwsA(isA<DevFSException>()));
   });
+
+  testWithoutContext('DevFS correctly records the elapsed time', () async {
+    final FileSystem fileSystem = MemoryFileSystem.test();
+    // final FakeDevFSWriter writer = FakeDevFSWriter();
+    final FakeVmServiceHost fakeVmServiceHost = FakeVmServiceHost(
+      requests: <VmServiceExpectation>[createDevFSRequest],
+      httpAddress: Uri.parse('http://localhost'),
+    );
+
+    final DevFS devFS = DevFS(
+      fakeVmServiceHost.vmService,
+      'test',
+      fileSystem.currentDirectory,
+      fileSystem: fileSystem,
+      logger: BufferLogger.test(),
+      osUtils: FakeOperatingSystemUtils(),
+      httpClient: FakeHttpClient.any(),
+      stopwatchFactory: FakeStopwatchFactory(stopwatches: <String, Stopwatch>{
+        'compile': FakeStopwatch()..elapsed = const Duration(seconds: 3),
+        'transfer': FakeStopwatch()..elapsed = const Duration(seconds: 5),
+      }),
+    );
+
+    await devFS.create();
+
+    final FakeResidentCompiler residentCompiler = FakeResidentCompiler();
+    residentCompiler.onRecompile = (Uri mainUri, List<Uri> invalidatedFiles) async {
+      fileSystem.file('lib/foo.txt.dill').createSync(recursive: true);
+      return const CompilerOutput('lib/foo.txt.dill', 0, <Uri>[]);
+    };
+
+    final UpdateFSReport report = await devFS.update(
+      mainUri: Uri.parse('lib/main.dart'),
+      generator: residentCompiler,
+      dillOutputPath: 'lib/foo.dill',
+      pathToReload: 'lib/foo.txt.dill',
+      trackWidgetCreation: false,
+      invalidatedFiles: <Uri>[],
+      packageConfig: PackageConfig.empty,
+    );
+
+    expect(report.success, true);
+    expect(report.compileDuration, const Duration(seconds: 3));
+    expect(report.transferDuration, const Duration(seconds: 5));
+  });
 }
 
 class FakeResidentCompiler extends Fake implements ResidentCompiler {

packages/flutter_tools/test/src/fakes.dart

@@ -535,3 +535,56 @@ class FakeOperatingSystemUtils extends Fake implements OperatingSystemUtils {
   @override
   Future<int> findFreePort({bool ipv6 = false}) async => 12345;
 }
+
+class FakeStopwatch implements Stopwatch {
+  @override
+  bool get isRunning => _isRunning;
+  bool _isRunning = false;
+
+  @override
+  void start() => _isRunning = true;
+
+  @override
+  void stop() => _isRunning = false;
+
+  @override
+  Duration elapsed = Duration.zero;
+
+  @override
+  int get elapsedMicroseconds => elapsed.inMicroseconds;
+
+  @override
+  int get elapsedMilliseconds => elapsed.inMilliseconds;
+
+  @override
+  int get elapsedTicks => elapsed.inMilliseconds;
+
+  @override
+  int get frequency => 1000;
+
+  @override
+  void reset() {
+    _isRunning = false;
+    elapsed = Duration.zero;
+  }
+
+  @override
+  String toString() => '$runtimeType $elapsed $isRunning';
+}
+
+class FakeStopwatchFactory implements StopwatchFactory {
+  FakeStopwatchFactory({
+    Stopwatch? stopwatch,
+    Map<String, Stopwatch>? stopwatches
+  }) : stopwatches = <String, Stopwatch>{
+         if (stopwatches != null) ...stopwatches,
+         if (stopwatch != null) '': stopwatch,
+       };
+
+  Map<String, Stopwatch> stopwatches;
+
+  @override
+  Stopwatch createStopwatch([String name = '']) {
+    return stopwatches[name] ?? FakeStopwatch();
+  }
+}