From 9929446ea3f3e8dd4e79be7bbb7d5cd19faefc6b Mon Sep 17 00:00:00 2001 From: jensjoha Date: Fri, 3 Jun 2022 08:41:14 +0200 Subject: [PATCH] Extra timing on hot reload (#104242) This PR adds extra timings for a hot reload. As an example, before a user might see > Performing hot reload... > Reloaded 1 of 788 libraries in 554ms. With this PR it would instead be something like > Performing hot reload... > Reloaded 1 of 788 libraries in 554ms (compile: 33 ms, reload: 153 ms, reassemble: 310 ms). --- .../lib/src/resident_runner.dart | 15 +++- packages/flutter_tools/lib/src/run_hot.dart | 16 +++- .../general.shard/resident_runner_test.dart | 89 +++++++++++++++++++ .../overall_experience_test.dart | 2 +- 4 files changed, 119 insertions(+), 3 deletions(-) diff --git a/packages/flutter_tools/lib/src/resident_runner.dart b/packages/flutter_tools/lib/src/resident_runner.dart index b5bbac33c7..0f1c3c698b 100644 --- a/packages/flutter_tools/lib/src/resident_runner.dart +++ b/packages/flutter_tools/lib/src/resident_runner.dart @@ -1486,7 +1486,7 @@ abstract class ResidentRunner extends ResidentHandlers { } class OperationResult { - OperationResult(this.code, this.message, { this.fatal = false, this.updateFSReport }); + OperationResult(this.code, this.message, { this.fatal = false, this.updateFSReport, this.extraTimings = const [] }); /// The result of the operation; a non-zero code indicates a failure. final int code; @@ -1494,6 +1494,9 @@ class OperationResult { /// A user facing message about the results of the operation. final String message; + /// User facing extra timing information about the operation. + final List extraTimings; + /// Whether this error should cause the runner to exit. final bool fatal; @@ -1504,6 +1507,16 @@ class OperationResult { static final OperationResult ok = OperationResult(0, ''); } +class OperationResultExtraTiming { + const OperationResultExtraTiming(this.description, this.timeInMs); + + /// A user facing short description of this timing. + final String description; + + /// The time this operation took in milliseconds. + final int timeInMs; +} + Future getMissingPackageHintForPlatform(TargetPlatform platform) async { switch (platform) { case TargetPlatform.android_arm: diff --git a/packages/flutter_tools/lib/src/run_hot.dart b/packages/flutter_tools/lib/src/run_hot.dart index 42bfe90810..5a0c0e8562 100644 --- a/packages/flutter_tools/lib/src/run_hot.dart +++ b/packages/flutter_tools/lib/src/run_hot.dart @@ -726,7 +726,14 @@ class HotRunner extends ResidentRunner { if (result.isOk) { final String elapsed = getElapsedAsMilliseconds(timer.elapsed); if (!silent) { - globals.printStatus('${result.message} in $elapsed.'); + if (result.extraTimings.isNotEmpty) { + final String extraTimingsString = result.extraTimings + .map((OperationResultExtraTiming e) => '${e.description}: ${e.timeInMs} ms') + .join(', '); + globals.printStatus('${result.message} in $elapsed ($extraTimingsString).'); + } else { + globals.printStatus('${result.message} in $elapsed.'); + } } } return result; @@ -898,6 +905,10 @@ class HotRunner extends ResidentRunner { if (!updatedDevFS.success) { return OperationResult(1, 'DevFS synchronization failed'); } + + final List extraTimings = []; + extraTimings.add(OperationResultExtraTiming('compile', updatedDevFS.compileDuration.inMilliseconds)); + String reloadMessage = 'Reloaded 0 libraries'; final Stopwatch reloadVMTimer = _stopwatchFactory.createStopwatch('reloadSources:vm')..start(); final Map firstReloadDetails = {}; @@ -920,6 +931,7 @@ class HotRunner extends ResidentRunner { _addBenchmarkData('hotReloadVMReloadMilliseconds', 0); } reloadVMTimer.stop(); + extraTimings.add(OperationResultExtraTiming('reload', reloadVMTimer.elapsedMilliseconds)); await evictDirtyAssets(); @@ -939,6 +951,7 @@ class HotRunner extends ResidentRunner { // Record time it took for Flutter to reassemble the application. reassembleTimer.stop(); _addBenchmarkData('hotReloadFlutterReassembleMilliseconds', reassembleTimer.elapsed.inMilliseconds); + extraTimings.add(OperationResultExtraTiming('reassemble', reassembleTimer.elapsedMilliseconds)); reloadTimer.stop(); final Duration reloadDuration = reloadTimer.elapsed; @@ -985,6 +998,7 @@ class HotRunner extends ResidentRunner { return OperationResult( reassembleResult.failedReassemble ? 1 : OperationResult.ok.code, reloadMessage, + extraTimings: extraTimings ); } diff --git a/packages/flutter_tools/test/general.shard/resident_runner_test.dart b/packages/flutter_tools/test/general.shard/resident_runner_test.dart index 092476d222..0013c18221 100644 --- a/packages/flutter_tools/test/general.shard/resident_runner_test.dart +++ b/packages/flutter_tools/test/general.shard/resident_runner_test.dart @@ -846,6 +846,95 @@ void main() { FeatureFlags: () => TestFeatureFlags(isSingleWidgetReloadEnabled: true), })); + testUsingContext('ResidentRunner reports hot reload time details', () => testbed.run(() async { + fakeVmServiceHost = FakeVmServiceHost(requests: [ + listViews, + FakeVmServiceRequest( + method: 'getVM', + jsonResponse: fakeVM.toJson(), + ), + listViews, + listViews, + FakeVmServiceRequest( + method: 'getVM', + jsonResponse: fakeVM.toJson(), + ), + const FakeVmServiceRequest( + method: 'reloadSources', + args: { + 'isolateId': '1', + 'pause': false, + 'rootLibUri': 'main.dart.incremental.dill', + }, + jsonResponse: { + 'type': 'ReloadReport', + 'success': true, + 'details': { + 'loadedLibraryCount': 1, + 'finalLibraryCount': 42, + }, + }, + ), + FakeVmServiceRequest( + method: 'getIsolate', + args: { + 'isolateId': '1', + }, + jsonResponse: fakeUnpausedIsolate.toJson(), + ), + FakeVmServiceRequest( + method: 'ext.flutter.fastReassemble', + args: { + 'isolateId': fakeUnpausedIsolate.id, + 'className': 'FOO', + }, + ), + ]); + final FakeDelegateFlutterDevice flutterDevice = FakeDelegateFlutterDevice( + device, + BuildInfo.debug, + FakeResidentCompiler(), + devFS, + )..vmService = fakeVmServiceHost.vmService; + residentRunner = HotRunner( + [ + flutterDevice, + ], + stayResident: false, + debuggingOptions: DebuggingOptions.enabled(BuildInfo.debug), + target: 'main.dart', + devtoolsHandler: createNoOpHandler, + ); + devFS.nextUpdateReport = UpdateFSReport( + success: true, + fastReassembleClassName: 'FOO', + invalidatedSourcesCount: 1, + ); + + final Completer futureConnectionInfo = Completer.sync(); + final Completer futureAppStart = Completer.sync(); + unawaited(residentRunner.attach( + appStartedCompleter: futureAppStart, + connectionInfoCompleter: futureConnectionInfo, + enableDevTools: true, + )); + + await futureAppStart.future; + await residentRunner.restart(); + + // The actual test: Expect to have compile, reload and reassemble times. + expect( + testLogger.statusText, + contains(RegExp(r'Reloaded 1 of 42 libraries in \d+ms ' + r'\(compile: \d+ ms, reload: \d+ ms, reassemble: \d+ ms\)\.'))); + }, overrides: { + FileSystem: () => MemoryFileSystem.test(), + Platform: () => FakePlatform(), + ProjectFileInvalidator: () => FakeProjectFileInvalidator(), + Usage: () => TestUsage(), + FeatureFlags: () => TestFeatureFlags(isSingleWidgetReloadEnabled: true), + })); + testUsingContext('ResidentRunner can send target platform to analytics from full restart', () => testbed.run(() async { fakeVmServiceHost = FakeVmServiceHost(requests: [ listViews, diff --git a/packages/flutter_tools/test/integration.shard/overall_experience_test.dart b/packages/flutter_tools/test/integration.shard/overall_experience_test.dart index 06461e88cf..09bb7248dc 100644 --- a/packages/flutter_tools/test/integration.shard/overall_experience_test.dart +++ b/packages/flutter_tools/test/integration.shard/overall_experience_test.dart @@ -375,7 +375,7 @@ void main() { return null; }), Barrier('Performing hot reload...'.padRight(progressMessageWidth), logging: true), - Multiple([RegExp(r'^Reloaded 0 libraries in [0-9]+ms\.$'), 'called reassemble', 'called paint'], handler: (String line) { + Multiple([RegExp(r'^Reloaded 0 libraries in [0-9]+ms \(compile: \d+ ms, reload: \d+ ms, reassemble: \d+ ms\)\.$'), 'called reassemble', 'called paint'], handler: (String line) { processManager.killPid(pid, ProcessSignal.sigusr2); return null; }),