[flutter_tools] Make flutter test -v print timing of different phases (#108864)
diff --git a/packages/flutter_tools/lib/executable.dart b/packages/flutter_tools/lib/executable.dart
index 3d69b03..944ec4a 100644
--- a/packages/flutter_tools/lib/executable.dart
+++ b/packages/flutter_tools/lib/executable.dart
@@ -193,7 +193,7 @@
RunCommand(verboseHelp: verboseHelp),
ScreenshotCommand(),
ShellCompletionCommand(),
- TestCommand(verboseHelp: verboseHelp),
+ TestCommand(verboseHelp: verboseHelp, verbose: verbose),
UpgradeCommand(verboseHelp: verboseHelp),
SymbolizeCommand(
stdio: globals.stdio,
diff --git a/packages/flutter_tools/lib/src/commands/test.dart b/packages/flutter_tools/lib/src/commands/test.dart
index 8473989..6e01be1 100644
--- a/packages/flutter_tools/lib/src/commands/test.dart
+++ b/packages/flutter_tools/lib/src/commands/test.dart
@@ -21,6 +21,7 @@
import '../test/coverage_collector.dart';
import '../test/event_printer.dart';
import '../test/runner.dart';
+import '../test/test_time_recorder.dart';
import '../test/test_wrapper.dart';
import '../test/watcher.dart';
@@ -64,6 +65,7 @@
bool verboseHelp = false,
this.testWrapper = const TestWrapper(),
this.testRunner = const FlutterTestRunner(),
+ this.verbose = false,
}) : assert(testWrapper != null) {
requiresPubspecYaml();
usesPubOption();
@@ -220,6 +222,8 @@
/// Interface for running the tester process.
final FlutterTestRunner testRunner;
+ final bool verbose;
+
@visibleForTesting
bool get isIntegrationTest => _isIntegrationTest;
bool _isIntegrationTest = false;
@@ -302,6 +306,11 @@
final String? excludeTags = stringArgDeprecated('exclude-tags');
final BuildInfo buildInfo = await getBuildInfo(forcedBuildMode: BuildMode.debug);
+ TestTimeRecorder? testTimeRecorder;
+ if (verbose) {
+ testTimeRecorder = TestTimeRecorder(globals.logger);
+ }
+
if (buildInfo.packageConfig['test_api'] == null) {
throwToolExit(
'Error: cannot run without a dependency on either "package:flutter_test" or "package:test". '
@@ -375,7 +384,8 @@
verbose: !machine,
libraryNames: <String>{projectName},
packagesPath: buildInfo.packagesPath,
- resolver: await CoverageCollector.getResolver(buildInfo.packagesPath)
+ resolver: await CoverageCollector.getResolver(buildInfo.packagesPath),
+ testTimeRecorder: testTimeRecorder,
);
}
@@ -427,6 +437,7 @@
}
}
+ final Stopwatch? testRunnerTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.TestRunner);
final int result = await testRunner.runTests(
testWrapper,
_testFiles,
@@ -452,18 +463,25 @@
totalShards: totalShards,
integrationTestDevice: integrationTestDevice,
integrationTestUserIdentifier: stringArgDeprecated(FlutterOptions.kDeviceUser),
+ testTimeRecorder: testTimeRecorder,
);
+ testTimeRecorder?.stop(TestTimePhases.TestRunner, testRunnerTimeRecorderStopwatch!);
if (collector != null) {
+ final Stopwatch? collectTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.CoverageDataCollect);
final bool collectionResult = await collector.collectCoverageData(
stringArgDeprecated('coverage-path'),
mergeCoverageData: boolArgDeprecated('merge-coverage'),
);
+ testTimeRecorder?.stop(TestTimePhases.CoverageDataCollect, collectTimeRecorderStopwatch!);
if (!collectionResult) {
+ testTimeRecorder?.print();
throwToolExit(null);
}
}
+ testTimeRecorder?.print();
+
if (result != 0) {
throwToolExit(null);
}
diff --git a/packages/flutter_tools/lib/src/test/coverage_collector.dart b/packages/flutter_tools/lib/src/test/coverage_collector.dart
index 5319f4a..c0c448d 100644
--- a/packages/flutter_tools/lib/src/test/coverage_collector.dart
+++ b/packages/flutter_tools/lib/src/test/coverage_collector.dart
@@ -15,11 +15,12 @@
import '../vmservice.dart';
import 'test_device.dart';
+import 'test_time_recorder.dart';
import 'watcher.dart';
/// A class that collects code coverage data during test runs.
class CoverageCollector extends TestWatcher {
- CoverageCollector({this.libraryNames, this.verbose = true, required this.packagesPath, this.resolver});
+ CoverageCollector({this.libraryNames, this.verbose = true, required this.packagesPath, this.resolver, this.testTimeRecorder});
/// True when log messages should be emitted.
final bool verbose;
@@ -38,6 +39,8 @@
final coverage.Resolver? resolver;
final Map<String, List<List<int>>> _ignoredLinesInFilesCache = <String, List<List<int>>>{};
+ final TestTimeRecorder? testTimeRecorder;
+
static Future<coverage.Resolver> getResolver(String? packagesPath) async {
try {
return await coverage.Resolver.create(packagesPath: packagesPath);
@@ -66,11 +69,13 @@
}
void _addHitmap(Map<String, coverage.HitMap> hitmap) {
+ final Stopwatch? stopwatch = testTimeRecorder?.start(TestTimePhases.CoverageAddHitmap);
if (_globalHitmap == null) {
_globalHitmap = hitmap;
} else {
_globalHitmap!.merge(hitmap);
}
+ testTimeRecorder?.stop(TestTimePhases.CoverageAddHitmap, stopwatch!);
}
/// The directory of the package for which coverage is being collected.
@@ -120,8 +125,12 @@
Future<void> collectCoverage(TestDevice testDevice, {@visibleForTesting Future<FlutterVmService> Function(Uri?)? connector}) async {
assert(testDevice != null);
+ final Stopwatch? totalTestTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.CoverageTotal);
+
Map<String, dynamic>? data;
+ final Stopwatch? collectTestTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.CoverageCollect);
+
final Future<void> processComplete = testDevice.finished.catchError(
(Object error) => throw Exception(
'Failed to collect coverage, test device terminated prematurely with '
@@ -144,15 +153,20 @@
await Future.any<void>(<Future<void>>[ processComplete, collectionComplete ]);
assert(data != null);
+ testTimeRecorder?.stop(TestTimePhases.CoverageCollect, collectTestTimeRecorderStopwatch!);
_logMessage('Merging coverage data...');
+ final Stopwatch? parseTestTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.CoverageParseJson);
final Map<String, coverage.HitMap> hitmap = coverage.HitMap.parseJsonSync(
data!['coverage'] as List<Map<String, dynamic>>,
checkIgnoredLines: true,
resolver: resolver ?? await CoverageCollector.getResolver(packageDirectory),
ignoredLinesInFilesCache: _ignoredLinesInFilesCache);
+ testTimeRecorder?.stop(TestTimePhases.CoverageParseJson, parseTestTimeRecorderStopwatch!);
+
_addHitmap(hitmap);
_logMessage('Done merging coverage data into global coverage map.');
+ testTimeRecorder?.stop(TestTimePhases.CoverageTotal, totalTestTimeRecorderStopwatch!);
}
/// Returns formatted coverage data once all coverage data has been collected.
diff --git a/packages/flutter_tools/lib/src/test/flutter_platform.dart b/packages/flutter_tools/lib/src/test/flutter_platform.dart
index 7734ff4..f8804d6 100644
--- a/packages/flutter_tools/lib/src/test/flutter_platform.dart
+++ b/packages/flutter_tools/lib/src/test/flutter_platform.dart
@@ -29,6 +29,7 @@
import 'test_compiler.dart';
import 'test_config.dart';
import 'test_device.dart';
+import 'test_time_recorder.dart';
import 'watcher.dart';
/// The address at which our WebSocket server resides and at which the sky_shell
@@ -63,6 +64,7 @@
PlatformPluginRegistration? platformPluginRegistration,
Device? integrationTestDevice,
String? integrationTestUserIdentifier,
+ TestTimeRecorder? testTimeRecorder,
}) {
assert(testWrapper != null);
assert(enableObservatory || (!debuggingOptions.startPaused && debuggingOptions.hostVmServicePort == null));
@@ -92,6 +94,7 @@
icudtlPath: icudtlPath,
integrationTestDevice: integrationTestDevice,
integrationTestUserIdentifier: integrationTestUserIdentifier,
+ testTimeRecorder: testTimeRecorder,
);
platformPluginRegistration(platform);
return platform;
@@ -286,6 +289,7 @@
this.icudtlPath,
this.integrationTestDevice,
this.integrationTestUserIdentifier,
+ this.testTimeRecorder,
}) : assert(shellPath != null);
final String shellPath;
@@ -301,6 +305,7 @@
final Uri? projectRootDirectory;
final FlutterProject? flutterProject;
final String? icudtlPath;
+ final TestTimeRecorder? testTimeRecorder;
/// The device to run the test on for Integration Tests.
///
@@ -454,7 +459,7 @@
// running this with a debugger attached. Initialize the resident
// compiler in this case.
if (debuggingOptions.startPaused) {
- compiler ??= TestCompiler(debuggingOptions.buildInfo, flutterProject, precompiledDillPath: precompiledDillPath);
+ compiler ??= TestCompiler(debuggingOptions.buildInfo, flutterProject, precompiledDillPath: precompiledDillPath, testTimeRecorder: testTimeRecorder);
final Uri testUri = globals.fs.file(testPath).uri;
// Trigger a compilation to initialize the resident compiler.
unawaited(compiler!.compile(testUri));
@@ -467,7 +472,7 @@
// Integration test device takes care of the compilation.
if (integrationTestDevice == null) {
// Lazily instantiate compiler so it is built only if it is actually used.
- compiler ??= TestCompiler(debuggingOptions.buildInfo, flutterProject);
+ compiler ??= TestCompiler(debuggingOptions.buildInfo, flutterProject, testTimeRecorder: testTimeRecorder);
mainDart = await compiler!.compile(globals.fs.file(mainDart).uri);
if (mainDart == null) {
@@ -479,6 +484,7 @@
globals.printTrace('test $ourTestCount: starting test device');
final TestDevice testDevice = _createTestDevice(ourTestCount);
+ final Stopwatch? testTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.Run);
final Future<StreamChannel<String>> remoteChannelFuture = testDevice.start(mainDart!);
finalizers.add(() async {
globals.printTrace('test $ourTestCount: ensuring test device is terminated.');
@@ -512,7 +518,10 @@
);
globals.printTrace('test $ourTestCount: finished');
+ testTimeRecorder?.stop(TestTimePhases.Run, testTimeRecorderStopwatch!);
+ final Stopwatch? watchTestTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.WatcherFinishedTest);
await watcher?.handleFinishedTest(testDevice);
+ testTimeRecorder?.stop(TestTimePhases.WatcherFinishedTest, watchTestTimeRecorderStopwatch!);
}()
]);
} on Exception catch (error, stackTrace) {
diff --git a/packages/flutter_tools/lib/src/test/flutter_web_platform.dart b/packages/flutter_tools/lib/src/test/flutter_web_platform.dart
index 4157538..15ef568 100644
--- a/packages/flutter_tools/lib/src/test/flutter_web_platform.dart
+++ b/packages/flutter_tools/lib/src/test/flutter_web_platform.dart
@@ -35,6 +35,7 @@
import '../web/memory_fs.dart';
import 'flutter_web_goldens.dart';
import 'test_compiler.dart';
+import 'test_time_recorder.dart';
class FlutterWebPlatform extends PlatformPlugin {
FlutterWebPlatform._(this._server, this._config, this._root, {
@@ -51,6 +52,7 @@
required Artifacts? artifacts,
required ProcessManager processManager,
required Cache cache,
+ TestTimeRecorder? testTimeRecorder,
}) : _fileSystem = fileSystem,
_flutterToolPackageConfig = flutterToolPackageConfig,
_chromiumLauncher = chromiumLauncher,
@@ -76,7 +78,7 @@
_server.mount(cascade.handler);
_testGoldenComparator = TestGoldenComparator(
shellPath,
- () => TestCompiler(buildInfo, flutterProject),
+ () => TestCompiler(buildInfo, flutterProject, testTimeRecorder: testTimeRecorder),
fileSystem: _fileSystem,
logger: _logger,
processManager: processManager,
@@ -120,6 +122,7 @@
required Artifacts? artifacts,
required ProcessManager processManager,
required Cache cache,
+ TestTimeRecorder? testTimeRecorder,
}) async {
final shelf_io.IOServer server = shelf_io.IOServer(await HttpMultiServer.loopback(0));
final PackageConfig packageConfig = await loadPackageConfigWithLogging(
@@ -149,6 +152,7 @@
nullAssertions: nullAssertions,
processManager: processManager,
cache: cache,
+ testTimeRecorder: testTimeRecorder,
);
}
diff --git a/packages/flutter_tools/lib/src/test/runner.dart b/packages/flutter_tools/lib/src/test/runner.dart
index 0ebf9e9..0bd675f 100644
--- a/packages/flutter_tools/lib/src/test/runner.dart
+++ b/packages/flutter_tools/lib/src/test/runner.dart
@@ -13,6 +13,7 @@
import '../web/memory_fs.dart';
import 'flutter_platform.dart' as loader;
import 'flutter_web_platform.dart';
+import 'test_time_recorder.dart';
import 'test_wrapper.dart';
import 'watcher.dart';
import 'web_test_compiler.dart';
@@ -51,6 +52,7 @@
int? totalShards,
Device? integrationTestDevice,
String? integrationTestUserIdentifier,
+ TestTimeRecorder? testTimeRecorder,
});
}
@@ -87,6 +89,7 @@
int? totalShards,
Device? integrationTestDevice,
String? integrationTestUserIdentifier,
+ TestTimeRecorder? testTimeRecorder,
}) async {
// Configure package:test to use the Flutter engine for child processes.
final String shellPath = globals.artifacts!.getArtifactPath(Artifact.flutterTester);
@@ -173,6 +176,7 @@
logger: globals.logger,
),
cache: globals.cache,
+ testTimeRecorder: testTimeRecorder,
);
},
);
@@ -204,6 +208,7 @@
icudtlPath: icudtlPath,
integrationTestDevice: integrationTestDevice,
integrationTestUserIdentifier: integrationTestUserIdentifier,
+ testTimeRecorder: testTimeRecorder,
);
try {
diff --git a/packages/flutter_tools/lib/src/test/test_compiler.dart b/packages/flutter_tools/lib/src/test/test_compiler.dart
index 7b119fd..dbeb6d3 100644
--- a/packages/flutter_tools/lib/src/test/test_compiler.dart
+++ b/packages/flutter_tools/lib/src/test/test_compiler.dart
@@ -16,6 +16,7 @@
import '../flutter_plugins.dart';
import '../globals.dart' as globals;
import '../project.dart';
+import 'test_time_recorder.dart';
/// A request to the [TestCompiler] for recompilation.
class CompilationRequest {
@@ -40,10 +41,12 @@
///
/// If [precompiledDillPath] is passed, it will be used to initialize the
/// compiler.
+ ///
+ /// If [testTimeRecorder] is passed, times will be recorded in it.
TestCompiler(
this.buildInfo,
this.flutterProject,
- { String? precompiledDillPath }
+ { String? precompiledDillPath, this.testTimeRecorder }
) : testFilePath = precompiledDillPath ?? globals.fs.path.join(
flutterProject!.directory.path,
getBuildDirectory(),
@@ -73,6 +76,7 @@
final BuildInfo buildInfo;
final String testFilePath;
final bool shouldCopyDillFile;
+ final TestTimeRecorder? testTimeRecorder;
ResidentCompiler? compiler;
@@ -139,6 +143,7 @@
final CompilationRequest request = compilationQueue.first;
globals.printTrace('Compiling ${request.mainUri}');
final Stopwatch compilerTime = Stopwatch()..start();
+ final Stopwatch? testTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.Compile);
bool firstCompile = false;
if (compiler == null) {
compiler = await createCompiler();
@@ -200,6 +205,7 @@
compiler!.reset();
}
globals.printTrace('Compiling ${request.mainUri} took ${compilerTime.elapsedMilliseconds}ms');
+ testTimeRecorder?.stop(TestTimePhases.Compile, testTimeRecorderStopwatch!);
// Only remove now when we finished processing the element
compilationQueue.removeAt(0);
}
diff --git a/packages/flutter_tools/lib/src/test/test_time_recorder.dart b/packages/flutter_tools/lib/src/test/test_time_recorder.dart
new file mode 100644
index 0000000..08ad333
--- /dev/null
+++ b/packages/flutter_tools/lib/src/test/test_time_recorder.dart
@@ -0,0 +1,129 @@
+// Copyright 2014 The Flutter 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:meta/meta.dart';
+
+import '../base/logger.dart';
+
+/// Utility class that can record time used in different phases of a test run.
+class TestTimeRecorder {
+ TestTimeRecorder(this.logger,
+ {this.stopwatchFactory = const StopwatchFactory()})
+ : _phaseRecords = List<TestTimeRecord>.generate(
+ TestTimePhases.values.length,
+ (_) => TestTimeRecord(stopwatchFactory),
+ );
+
+ final List<TestTimeRecord> _phaseRecords;
+ final Logger logger;
+ final StopwatchFactory stopwatchFactory;
+
+ Stopwatch start(TestTimePhases phase) {
+ return _phaseRecords[phase.index].start();
+ }
+
+ void stop(TestTimePhases phase, Stopwatch stopwatch) {
+ _phaseRecords[phase.index].stop(stopwatch);
+ }
+
+ void print() {
+ for (final TestTimePhases phase in TestTimePhases.values) {
+ logger.printTrace(_getPrintStringForPhase(phase));
+ }
+ }
+
+ @visibleForTesting
+ List<String> getPrintAsListForTesting() {
+ final List<String> result = <String>[];
+ for (final TestTimePhases phase in TestTimePhases.values) {
+ result.add(_getPrintStringForPhase(phase));
+ }
+ return result;
+ }
+
+ @visibleForTesting
+ Stopwatch getPhaseWallClockStopwatchForTesting(final TestTimePhases phase) {
+ return _phaseRecords[phase.index]._wallClockRuntime;
+ }
+
+ String _getPrintStringForPhase(final TestTimePhases phase) {
+ assert(_phaseRecords[phase.index].isDone());
+ return 'Runtime for phase ${phase.name}: ${_phaseRecords[phase.index]}';
+ }
+}
+
+/// Utility class that can record time used in a specific phase of a test run.
+class TestTimeRecord {
+ TestTimeRecord(this.stopwatchFactory)
+ : _wallClockRuntime = stopwatchFactory.createStopwatch();
+
+ final StopwatchFactory stopwatchFactory;
+ Duration _combinedRuntime = Duration.zero;
+ final Stopwatch _wallClockRuntime;
+ int _currentlyRunningCount = 0;
+
+ Stopwatch start() {
+ final Stopwatch stopwatch = stopwatchFactory.createStopwatch()..start();
+ if (_currentlyRunningCount == 0) {
+ _wallClockRuntime.start();
+ }
+ _currentlyRunningCount++;
+ return stopwatch;
+ }
+
+ void stop(Stopwatch stopwatch) {
+ _currentlyRunningCount--;
+ if (_currentlyRunningCount == 0) {
+ _wallClockRuntime.stop();
+ }
+ _combinedRuntime = _combinedRuntime + stopwatch.elapsed;
+ assert(_currentlyRunningCount >= 0);
+ }
+
+ @override
+ String toString() {
+ return 'Wall-clock: ${_wallClockRuntime.elapsed}; combined: $_combinedRuntime.';
+ }
+
+ bool isDone() {
+ return _currentlyRunningCount == 0;
+ }
+}
+
+enum TestTimePhases {
+ /// Covers entire TestRunner run, i.e. from the test runner was asked to `runTests` until it is done.
+ ///
+ /// This implicitly includes all the other phases.
+ TestRunner,
+
+ /// Covers time spent compiling, including subsequent copying of files.
+ Compile,
+
+ /// Covers time spent running, i.e. from starting the test device until the test has finished.
+ Run,
+
+ /// Covers all time spent collecting coverage.
+ CoverageTotal,
+
+ /// Covers collecting the coverage, but not parsing nor adding to hit map.
+ ///
+ /// This is included in [CoverageTotal]
+ CoverageCollect,
+
+ /// Covers parsing the json from the coverage collected.
+ ///
+ /// This is included in [CoverageTotal]
+ CoverageParseJson,
+
+ /// Covers adding the parsed coverage to the hitmap.
+ ///
+ /// This is included in [CoverageTotal]
+ CoverageAddHitmap,
+
+ /// Covers time spent in `collectCoverageData`, mostly formatting and writing coverage data to file.
+ CoverageDataCollect,
+
+ /// Covers time spend in the Watchers `handleFinishedTest` call. This is probably collecting coverage.
+ WatcherFinishedTest,
+}
diff --git a/packages/flutter_tools/test/commands.shard/hermetic/test_test.dart b/packages/flutter_tools/test/commands.shard/hermetic/test_test.dart
index 816a83c..ecf8193 100644
--- a/packages/flutter_tools/test/commands.shard/hermetic/test_test.dart
+++ b/packages/flutter_tools/test/commands.shard/hermetic/test_test.dart
@@ -11,6 +11,7 @@
import 'package:file/memory.dart';
import 'package:flutter_tools/src/base/common.dart';
import 'package:flutter_tools/src/base/file_system.dart';
+import 'package:flutter_tools/src/base/logger.dart';
import 'package:flutter_tools/src/build_info.dart';
import 'package:flutter_tools/src/cache.dart';
import 'package:flutter_tools/src/commands/test.dart';
@@ -18,6 +19,7 @@
import 'package:flutter_tools/src/project.dart';
import 'package:flutter_tools/src/runner/flutter_command.dart';
import 'package:flutter_tools/src/test/runner.dart';
+import 'package:flutter_tools/src/test/test_time_recorder.dart';
import 'package:flutter_tools/src/test/test_wrapper.dart';
import 'package:flutter_tools/src/test/watcher.dart';
import 'package:meta/meta.dart';
@@ -25,6 +27,7 @@
import '../../src/common.dart';
import '../../src/context.dart';
import '../../src/fake_devices.dart';
+import '../../src/logging_logger.dart';
import '../../src/test_flutter_command_runner.dart';
const String _pubspecContents = '''
@@ -57,6 +60,7 @@
void main() {
Cache.disableLocking();
MemoryFileSystem fs;
+ LoggingLogger logger;
setUp(() {
fs = MemoryFileSystem.test();
@@ -70,6 +74,8 @@
fs.directory('/package/integration_test').childFile('some_integration_test.dart').createSync(recursive: true);
fs.currentDirectory = '/package';
+
+ logger = LoggingLogger();
});
testUsingContext('Missing dependencies in pubspec',
@@ -90,6 +96,7 @@
}, overrides: <Type, Generator>{
FileSystem: () => fs,
ProcessManager: () => FakeProcessManager.any(),
+ Logger: () => logger,
});
testUsingContext('Missing dependencies in pubspec for integration tests',
@@ -317,6 +324,58 @@
Cache: () => Cache.test(processManager: FakeProcessManager.any()),
});
+ testUsingContext('Verbose prints phase timings', () async {
+ final FakeFlutterTestRunner testRunner = FakeFlutterTestRunner(0, const Duration(milliseconds: 1));
+
+ final TestCommand testCommand = TestCommand(testRunner: testRunner, verbose: true);
+ final CommandRunner<void> commandRunner =
+ createTestCommandRunner(testCommand);
+
+ await commandRunner.run(const <String>[
+ 'test',
+ '--no-pub',
+ '--',
+ 'test/fake_test.dart',
+ ]);
+
+ // Expect one message for each phase.
+ final List<String> logPhaseMessages = logger.messages.where((String m) => m.startsWith('Runtime for phase ')).toList();
+ expect(logPhaseMessages, hasLength(TestTimePhases.values.length));
+
+ // As we force the `runTests` command to take at least 1 ms expect at least
+ // one phase to take a non-zero amount of time.
+ final List<String> logPhaseMessagesNonZero = logPhaseMessages.where((String m) => !m.contains(Duration.zero.toString())).toList();
+ expect(logPhaseMessagesNonZero, isNotEmpty);
+ }, overrides: <Type, Generator>{
+ FileSystem: () => fs,
+ ProcessManager: () => FakeProcessManager.any(),
+ Cache: () => Cache.test(processManager: FakeProcessManager.any()),
+ Logger: () => logger,
+ });
+
+ testUsingContext('Non-verbose does not prints phase timings', () async {
+ final FakeFlutterTestRunner testRunner = FakeFlutterTestRunner(0, const Duration(milliseconds: 1));
+
+ final TestCommand testCommand = TestCommand(testRunner: testRunner);
+ final CommandRunner<void> commandRunner =
+ createTestCommandRunner(testCommand);
+
+ await commandRunner.run(const <String>[
+ 'test',
+ '--no-pub',
+ '--',
+ 'test/fake_test.dart',
+ ]);
+
+ final List<String> logPhaseMessages = logger.messages.where((String m) => m.startsWith('Runtime for phase ')).toList();
+ expect(logPhaseMessages, isEmpty);
+ }, overrides: <Type, Generator>{
+ FileSystem: () => fs,
+ ProcessManager: () => FakeProcessManager.any(),
+ Cache: () => Cache.test(processManager: FakeProcessManager.any()),
+ Logger: () => logger,
+ });
+
testUsingContext('Pipes different args when running Integration Tests', () async {
final FakePackageTest fakePackageTest = FakePackageTest();
@@ -728,9 +787,10 @@
}
class FakeFlutterTestRunner implements FlutterTestRunner {
- FakeFlutterTestRunner(this.exitCode);
+ FakeFlutterTestRunner(this.exitCode, [this.leastRunTime]);
int exitCode;
+ Duration leastRunTime;
bool lastEnableObservatoryValue;
DebuggingOptions lastDebuggingOptionsValue;
@@ -768,9 +828,15 @@
int totalShards,
Device integrationTestDevice,
String integrationTestUserIdentifier,
+ TestTimeRecorder testTimeRecorder,
}) async {
lastEnableObservatoryValue = enableObservatory;
lastDebuggingOptionsValue = debuggingOptions;
+
+ if (leastRunTime != null) {
+ await Future<void>.delayed(leastRunTime);
+ }
+
return exitCode;
}
}
diff --git a/packages/flutter_tools/test/general.shard/coverage_collector_test.dart b/packages/flutter_tools/test/general.shard/coverage_collector_test.dart
index e63db2b..0f473c3 100644
--- a/packages/flutter_tools/test/general.shard/coverage_collector_test.dart
+++ b/packages/flutter_tools/test/general.shard/coverage_collector_test.dart
@@ -8,11 +8,13 @@
import 'package:coverage/src/hitmap.dart';
import 'package:flutter_tools/src/test/coverage_collector.dart';
import 'package:flutter_tools/src/test/test_device.dart' show TestDevice;
+import 'package:flutter_tools/src/test/test_time_recorder.dart';
import 'package:stream_channel/stream_channel.dart' show StreamChannel;
import 'package:vm_service/vm_service.dart';
import '../src/common.dart';
import '../src/fake_vm_services.dart';
+import '../src/logging_logger.dart';
void main() {
testWithoutContext('Coverage collector Can handle coverage SentinelException', () async {
@@ -341,26 +343,13 @@
Directory? tempDir;
try {
tempDir = Directory.systemTemp.createTempSync('flutter_coverage_collector_test.');
- final File file = File('${tempDir.path}/packages.json');
- file.writeAsStringSync(jsonEncode(<String, dynamic>{
- 'configVersion': 2,
- 'packages': <Map<String, String>>[
- <String, String>{
- 'name': 'foo',
- 'rootUri': 'foo',
- },
- <String, String>{
- 'name': 'bar',
- 'rootUri': 'bar',
- },
- ],
- }));
+ final File packagesFile = writeFooBarPackagesJson(tempDir);
final Directory fooDir = Directory('${tempDir.path}/foo/');
fooDir.createSync();
final File fooFile = File('${fooDir.path}/foo.dart');
fooFile.writeAsStringSync('hit\nnohit but ignored // coverage:ignore-line\nhit\n');
- final String packagesPath = file.path;
+ final String packagesPath = packagesFile.path;
final CoverageCollector collector = CoverageCollector(
libraryNames: <String>{'foo', 'bar'},
verbose: false,
@@ -408,6 +397,61 @@
tempDir?.deleteSync(recursive: true);
}
});
+
+ testWithoutContext('Coverage collector records test timings when provided TestTimeRecorder', () async {
+ Directory? tempDir;
+ try {
+ tempDir = Directory.systemTemp.createTempSync('flutter_coverage_collector_test.');
+ final File packagesFile = writeFooBarPackagesJson(tempDir);
+ final Directory fooDir = Directory('${tempDir.path}/foo/');
+ fooDir.createSync();
+ final File fooFile = File('${fooDir.path}/foo.dart');
+ fooFile.writeAsStringSync('hit\nnohit but ignored // coverage:ignore-line\nhit\n');
+
+ final String packagesPath = packagesFile.path;
+ final LoggingLogger logger = LoggingLogger();
+ final TestTimeRecorder testTimeRecorder = TestTimeRecorder(logger);
+ final CoverageCollector collector = CoverageCollector(
+ libraryNames: <String>{'foo', 'bar'},
+ verbose: false,
+ packagesPath: packagesPath,
+ resolver: await CoverageCollector.getResolver(packagesPath),
+ testTimeRecorder: testTimeRecorder
+ );
+ await collector.collectCoverage(TestTestDevice(), connector: (Uri? uri) async {
+ return createFakeVmServiceHostWithFooAndBar().vmService;
+ });
+
+ // Expect one message for each phase.
+ final List<String> logPhaseMessages = testTimeRecorder.getPrintAsListForTesting().where((String m) => m.startsWith('Runtime for phase ')).toList();
+ expect(logPhaseMessages, hasLength(TestTimePhases.values.length));
+
+ // Several phases actually does something, but here we just expect at
+ // least one phase to take a non-zero amount of time.
+ final List<String> logPhaseMessagesNonZero = logPhaseMessages.where((String m) => !m.contains(Duration.zero.toString())).toList();
+ expect(logPhaseMessagesNonZero, isNotEmpty);
+ } finally {
+ tempDir?.deleteSync(recursive: true);
+ }
+ });
+}
+
+File writeFooBarPackagesJson(Directory tempDir) {
+ final File file = File('${tempDir.path}/packages.json');
+ file.writeAsStringSync(jsonEncode(<String, dynamic>{
+ 'configVersion': 2,
+ 'packages': <Map<String, String>>[
+ <String, String>{
+ 'name': 'foo',
+ 'rootUri': 'foo',
+ },
+ <String, String>{
+ 'name': 'bar',
+ 'rootUri': 'bar',
+ },
+ ],
+ }));
+ return file;
}
FakeVmServiceHost createFakeVmServiceHostWithFooAndBar() {
diff --git a/packages/flutter_tools/test/general.shard/devfs_test.dart b/packages/flutter_tools/test/general.shard/devfs_test.dart
index 3d3caf9..63fd077 100644
--- a/packages/flutter_tools/test/general.shard/devfs_test.dart
+++ b/packages/flutter_tools/test/general.shard/devfs_test.dart
@@ -16,7 +16,6 @@
import 'package:flutter_tools/src/base/logger.dart';
import 'package:flutter_tools/src/base/os.dart';
import 'package:flutter_tools/src/base/platform.dart';
-import 'package:flutter_tools/src/base/terminal.dart';
import 'package:flutter_tools/src/build_info.dart';
import 'package:flutter_tools/src/build_system/targets/shader_compiler.dart';
import 'package:flutter_tools/src/compile.dart';
@@ -30,6 +29,7 @@
import '../src/fake_http_client.dart';
import '../src/fake_vm_services.dart';
import '../src/fakes.dart';
+import '../src/logging_logger.dart';
final FakeVmServiceRequest createDevFSRequest = FakeVmServiceRequest(
method: '_createDevFS',
@@ -716,27 +716,6 @@
}
}
-class LoggingLogger extends BufferLogger {
- LoggingLogger() : super.test();
-
- List<String> messages = <String>[];
-
- @override
- void printError(String message, {StackTrace? stackTrace, bool? emphasis, TerminalColor? color, int? indent, int? hangingIndent, bool? wrap}) {
- messages.add(message);
- }
-
- @override
- void printStatus(String message, {bool? emphasis, TerminalColor? color, bool? newline, int? indent, int? hangingIndent, bool? wrap}) {
- messages.add(message);
- }
-
- @override
- void printTrace(String message) {
- messages.add(message);
- }
-}
-
class FakeBundle extends AssetBundle {
@override
List<File> get additionalDependencies => <File>[];
diff --git a/packages/flutter_tools/test/general.shard/test/test_compiler_test.dart b/packages/flutter_tools/test/general.shard/test/test_compiler_test.dart
index 5ff3c75..bd2bb06 100644
--- a/packages/flutter_tools/test/general.shard/test/test_compiler_test.dart
+++ b/packages/flutter_tools/test/general.shard/test/test_compiler_test.dart
@@ -11,11 +11,13 @@
import 'package:flutter_tools/src/compile.dart';
import 'package:flutter_tools/src/project.dart';
import 'package:flutter_tools/src/test/test_compiler.dart';
+import 'package:flutter_tools/src/test/test_time_recorder.dart';
import 'package:package_config/package_config_types.dart';
import 'package:test/fake.dart';
import '../../src/common.dart';
import '../../src/context.dart';
+import '../../src/logging_logger.dart';
final Platform linuxPlatform = FakePlatform(
environment: <String, String>{},
@@ -33,6 +35,7 @@
void main() {
late FakeResidentCompiler residentCompiler;
late FileSystem fileSystem;
+ late LoggingLogger logger;
setUp(() {
fileSystem = MemoryFileSystem.test();
@@ -40,6 +43,7 @@
fileSystem.file('test/foo.dart').createSync(recursive: true);
fileSystem.file('.packages').createSync();
residentCompiler = FakeResidentCompiler(fileSystem);
+ logger = LoggingLogger();
});
testUsingContext('TestCompiler reports a dill file when compile is successful', () async {
@@ -92,6 +96,34 @@
Logger: () => BufferLogger.test(),
});
+
+ testUsingContext('TestCompiler records test timings when provided TestTimeRecorder', () async {
+ residentCompiler.compilerOutput = const CompilerOutput('abc.dill', 0, <Uri>[]);
+ final TestTimeRecorder testTimeRecorder = TestTimeRecorder(logger);
+ final FakeTestCompiler testCompiler = FakeTestCompiler(
+ debugBuild,
+ FlutterProject.fromDirectoryTest(fileSystem.currentDirectory),
+ residentCompiler,
+ testTimeRecorder: testTimeRecorder,
+ );
+ expect(await testCompiler.compile(Uri.parse('test/foo.dart')), 'test/foo.dart.dill');
+ testTimeRecorder.print();
+
+ // Expect one message for each phase.
+ final List<String> logPhaseMessages = logger.messages.where((String m) => m.startsWith('Runtime for phase ')).toList();
+ expect(logPhaseMessages, hasLength(TestTimePhases.values.length));
+
+ // As the compile method adds a job to a queue etc we expect at
+ // least one phase to take a non-zero amount of time.
+ final List<String> logPhaseMessagesNonZero = logPhaseMessages.where((String m) => !m.contains(Duration.zero.toString())).toList();
+ expect(logPhaseMessagesNonZero, isNotEmpty);
+ }, overrides: <Type, Generator>{
+ FileSystem: () => fileSystem,
+ Platform: () => linuxPlatform,
+ ProcessManager: () => FakeProcessManager.any(),
+ Logger: () => logger,
+ });
+
testUsingContext('TestCompiler disposing test compiler shuts down backing compiler', () async {
final FakeTestCompiler testCompiler = FakeTestCompiler(
debugBuild,
@@ -171,6 +203,7 @@
super.flutterProject,
this.residentCompiler, {
super.precompiledDillPath,
+ super.testTimeRecorder,
}
);
diff --git a/packages/flutter_tools/test/general.shard/test/test_time_recorder_test.dart b/packages/flutter_tools/test/general.shard/test/test_time_recorder_test.dart
new file mode 100644
index 0000000..d158286
--- /dev/null
+++ b/packages/flutter_tools/test/general.shard/test/test_time_recorder_test.dart
@@ -0,0 +1,60 @@
+// Copyright 2014 The Flutter 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_tools/src/test/test_time_recorder.dart';
+
+import '../../src/common.dart';
+import '../../src/fakes.dart';
+import '../../src/logging_logger.dart';
+
+void main() {
+ testWithoutContext('Test phases prints correctly', () {
+ const Duration zero = Duration.zero;
+ const Duration combinedDuration = Duration(seconds: 42);
+ const Duration wallClockDuration = Duration(seconds: 21);
+
+ for (final TestTimePhases phase in TestTimePhases.values) {
+ final TestTimeRecorder recorder = createRecorderWithTimesForPhase(
+ phase, combinedDuration, wallClockDuration);
+ final Set<String> prints = recorder.getPrintAsListForTesting().toSet();
+
+ // Expect one entry per phase.
+ expect(prints, hasLength(TestTimePhases.values.length));
+
+ // Expect this phase to have the specified times.
+ expect(
+ prints,
+ contains('Runtime for phase ${phase.name}: '
+ 'Wall-clock: $wallClockDuration; combined: $combinedDuration.'),
+ );
+
+ // Expect all other phases to say 0.
+ for (final TestTimePhases innerPhase in TestTimePhases.values) {
+ if (phase == innerPhase) {
+ continue;
+ }
+ expect(
+ prints,
+ contains('Runtime for phase ${innerPhase.name}: '
+ 'Wall-clock: $zero; combined: $zero.'),
+ );
+ }
+ }
+ });
+}
+
+TestTimeRecorder createRecorderWithTimesForPhase(TestTimePhases phase,
+ Duration combinedDuration, Duration wallClockDuration) {
+ final LoggingLogger logger = LoggingLogger();
+ final TestTimeRecorder recorder =
+ TestTimeRecorder(logger, stopwatchFactory: FakeStopwatchFactory());
+ final FakeStopwatch combinedStopwatch =
+ recorder.start(phase) as FakeStopwatch;
+ final FakeStopwatch wallClockStopwatch =
+ recorder.getPhaseWallClockStopwatchForTesting(phase) as FakeStopwatch;
+ wallClockStopwatch.elapsed = wallClockDuration;
+ combinedStopwatch.elapsed = combinedDuration;
+ recorder.stop(phase, combinedStopwatch);
+ return recorder;
+}
diff --git a/packages/flutter_tools/test/src/logging_logger.dart b/packages/flutter_tools/test/src/logging_logger.dart
new file mode 100644
index 0000000..96a77a3
--- /dev/null
+++ b/packages/flutter_tools/test/src/logging_logger.dart
@@ -0,0 +1,27 @@
+// Copyright 2014 The Flutter 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_tools/src/base/logger.dart';
+import 'package:flutter_tools/src/base/terminal.dart';
+
+class LoggingLogger extends BufferLogger {
+ LoggingLogger() : super.test();
+
+ List<String> messages = <String>[];
+
+ @override
+ void printError(String message, {StackTrace? stackTrace, bool? emphasis, TerminalColor? color, int? indent, int? hangingIndent, bool? wrap}) {
+ messages.add(message);
+ }
+
+ @override
+ void printStatus(String message, {bool? emphasis, TerminalColor? color, bool? newline, int? indent, int? hangingIndent, bool? wrap}) {
+ messages.add(message);
+ }
+
+ @override
+ void printTrace(String message) {
+ messages.add(message);
+ }
+}
