Unverified Commit 9929446e authored by jensjoha's avatar jensjoha Committed by GitHub

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).
parent a8fd63a1
......@@ -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 <OperationResultExtraTiming>[] });
/// 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<OperationResultExtraTiming> 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<String> getMissingPackageHintForPlatform(TargetPlatform platform) async {
switch (platform) {
case TargetPlatform.android_arm:
......
......@@ -726,9 +726,16 @@ class HotRunner extends ResidentRunner {
if (result.isOk) {
final String elapsed = getElapsedAsMilliseconds(timer.elapsed);
if (!silent) {
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<OperationResultExtraTiming> extraTimings = <OperationResultExtraTiming>[];
extraTimings.add(OperationResultExtraTiming('compile', updatedDevFS.compileDuration.inMilliseconds));
String reloadMessage = 'Reloaded 0 libraries';
final Stopwatch reloadVMTimer = _stopwatchFactory.createStopwatch('reloadSources:vm')..start();
final Map<String, Object> firstReloadDetails = <String, Object>{};
......@@ -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
);
}
......
......@@ -846,6 +846,95 @@ void main() {
FeatureFlags: () => TestFeatureFlags(isSingleWidgetReloadEnabled: true),
}));
testUsingContext('ResidentRunner reports hot reload time details', () => testbed.run(() async {
fakeVmServiceHost = FakeVmServiceHost(requests: <VmServiceExpectation>[
listViews,
FakeVmServiceRequest(
method: 'getVM',
jsonResponse: fakeVM.toJson(),
),
listViews,
listViews,
FakeVmServiceRequest(
method: 'getVM',
jsonResponse: fakeVM.toJson(),
),
const FakeVmServiceRequest(
method: 'reloadSources',
args: <String, Object>{
'isolateId': '1',
'pause': false,
'rootLibUri': 'main.dart.incremental.dill',
},
jsonResponse: <String, Object>{
'type': 'ReloadReport',
'success': true,
'details': <String, Object>{
'loadedLibraryCount': 1,
'finalLibraryCount': 42,
},
},
),
FakeVmServiceRequest(
method: 'getIsolate',
args: <String, Object>{
'isolateId': '1',
},
jsonResponse: fakeUnpausedIsolate.toJson(),
),
FakeVmServiceRequest(
method: 'ext.flutter.fastReassemble',
args: <String, Object>{
'isolateId': fakeUnpausedIsolate.id,
'className': 'FOO',
},
),
]);
final FakeDelegateFlutterDevice flutterDevice = FakeDelegateFlutterDevice(
device,
BuildInfo.debug,
FakeResidentCompiler(),
devFS,
)..vmService = fakeVmServiceHost.vmService;
residentRunner = HotRunner(
<FlutterDevice>[
flutterDevice,
],
stayResident: false,
debuggingOptions: DebuggingOptions.enabled(BuildInfo.debug),
target: 'main.dart',
devtoolsHandler: createNoOpHandler,
);
devFS.nextUpdateReport = UpdateFSReport(
success: true,
fastReassembleClassName: 'FOO',
invalidatedSourcesCount: 1,
);
final Completer<DebugConnectionInfo> futureConnectionInfo = Completer<DebugConnectionInfo>.sync();
final Completer<void> futureAppStart = Completer<void>.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: <Type, Generator>{
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: <VmServiceExpectation>[
listViews,
......
......@@ -375,7 +375,7 @@ void main() {
return null;
}),
Barrier('Performing hot reload...'.padRight(progressMessageWidth), logging: true),
Multiple(<Pattern>[RegExp(r'^Reloaded 0 libraries in [0-9]+ms\.$'), 'called reassemble', 'called paint'], handler: (String line) {
Multiple(<Pattern>[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;
}),
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment