[flutter_tools] Make flutter test -v print timing of different phases (#108864)

packages/flutter_tools/lib/executable.dart

@@ -193,7 +193,7 @@ List<FlutterCommand> generateCommands({
   RunCommand(verboseHelp: verboseHelp),
   ScreenshotCommand(),
   ShellCompletionCommand(),
-  TestCommand(verboseHelp: verboseHelp),
+  TestCommand(verboseHelp: verboseHelp, verbose: verbose),
   UpgradeCommand(verboseHelp: verboseHelp),
   SymbolizeCommand(
     stdio: globals.stdio,

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

@@ -21,6 +21,7 @@ import '../runner/flutter_command.dart';
 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 @@ class TestCommand extends FlutterCommand with DeviceBasedDevelopmentArtifacts {
     bool verboseHelp = false,
     this.testWrapper = const TestWrapper(),
     this.testRunner = const FlutterTestRunner(),
+    this.verbose = false,
   }) : assert(testWrapper != null) {
     requiresPubspecYaml();
     usesPubOption();
@@ -220,6 +222,8 @@ class TestCommand extends FlutterCommand with DeviceBasedDevelopmentArtifacts {
   /// Interface for running the tester process.
   final FlutterTestRunner testRunner;
 
+  final bool verbose;
+
   @visibleForTesting
   bool get isIntegrationTest => _isIntegrationTest;
   bool _isIntegrationTest = false;
@@ -302,6 +306,11 @@ class TestCommand extends FlutterCommand with DeviceBasedDevelopmentArtifacts {
     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 @@ class TestCommand extends FlutterCommand with DeviceBasedDevelopmentArtifacts {
         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 @@ class TestCommand extends FlutterCommand with DeviceBasedDevelopmentArtifacts {
       }
     }
 
+    final Stopwatch? testRunnerTimeRecorderStopwatch = testTimeRecorder?.start(TestTimePhases.TestRunner);
     final int result = await testRunner.runTests(
       testWrapper,
       _testFiles,
@@ -452,18 +463,25 @@ class TestCommand extends FlutterCommand with DeviceBasedDevelopmentArtifacts {
       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);
     }

packages/flutter_tools/lib/src/test/coverage_collector.dart

@@ -15,11 +15,12 @@ import '../globals.dart' as globals;
 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 @@ class CoverageCollector extends TestWatcher {
   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 @@ class CoverageCollector extends TestWatcher {
   }
 
   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 @@ class CoverageCollector extends TestWatcher {
   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 @@ class CoverageCollector extends TestWatcher {
 
     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.

packages/flutter_tools/lib/src/test/flutter_platform.dart

@@ -29,6 +29,7 @@ import 'integration_test_device.dart';
 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 @@ FlutterPlatform installHook({
   PlatformPluginRegistration? platformPluginRegistration,
   Device? integrationTestDevice,
   String? integrationTestUserIdentifier,
+  TestTimeRecorder? testTimeRecorder,
 }) {
   assert(testWrapper != null);
   assert(enableObservatory || (!debuggingOptions.startPaused && debuggingOptions.hostVmServicePort == null));
@@ -92,6 +94,7 @@ FlutterPlatform installHook({
     icudtlPath: icudtlPath,
     integrationTestDevice: integrationTestDevice,
     integrationTestUserIdentifier: integrationTestUserIdentifier,
+    testTimeRecorder: testTimeRecorder,
   );
   platformPluginRegistration(platform);
   return platform;
@@ -286,6 +289,7 @@ class FlutterPlatform extends PlatformPlugin {
     this.icudtlPath,
     this.integrationTestDevice,
     this.integrationTestUserIdentifier,
+    this.testTimeRecorder,
   }) : assert(shellPath != null);
 
   final String shellPath;
@@ -301,6 +305,7 @@ class FlutterPlatform extends PlatformPlugin {
   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 @@ class FlutterPlatform extends PlatformPlugin {
         // 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 @@ class FlutterPlatform extends PlatformPlugin {
         // 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 @@ class FlutterPlatform extends PlatformPlugin {
 
       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 @@ class FlutterPlatform extends PlatformPlugin {
           );
 
           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) {

packages/flutter_tools/lib/src/test/flutter_web_platform.dart

@@ -35,6 +35,7 @@ import '../web/compile.dart';
 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 @@ class FlutterWebPlatform extends PlatformPlugin {
     required Artifacts? artifacts,
     required ProcessManager processManager,
     required Cache cache,
+    TestTimeRecorder? testTimeRecorder,
   }) : _fileSystem = fileSystem,
       _flutterToolPackageConfig = flutterToolPackageConfig,
       _chromiumLauncher = chromiumLauncher,
@@ -76,7 +78,7 @@ class FlutterWebPlatform extends PlatformPlugin {
     _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 @@ class FlutterWebPlatform extends PlatformPlugin {
     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 @@ class FlutterWebPlatform extends PlatformPlugin {
       nullAssertions: nullAssertions,
       processManager: processManager,
       cache: cache,
+      testTimeRecorder: testTimeRecorder,
     );
   }
 

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

@@ -13,6 +13,7 @@ import '../web/chrome.dart';
 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 @@ abstract class FlutterTestRunner {
     int? totalShards,
     Device? integrationTestDevice,
     String? integrationTestUserIdentifier,
+    TestTimeRecorder? testTimeRecorder,
   });
 }
 
@@ -87,6 +89,7 @@ class _FlutterTestRunnerImpl implements FlutterTestRunner {
     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 @@ class _FlutterTestRunnerImpl implements FlutterTestRunner {
               logger: globals.logger,
             ),
             cache: globals.cache,
+            testTimeRecorder: testTimeRecorder,
           );
         },
       );
@@ -204,6 +208,7 @@ class _FlutterTestRunnerImpl implements FlutterTestRunner {
       icudtlPath: icudtlPath,
       integrationTestDevice: integrationTestDevice,
       integrationTestUserIdentifier: integrationTestUserIdentifier,
+      testTimeRecorder: testTimeRecorder,
     );
 
     try {

packages/flutter_tools/lib/src/test/test_compiler.dart

@@ -16,6 +16,7 @@ import '../compile.dart';
 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 @@ class TestCompiler {
   ///
   /// 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 @@ class TestCompiler {
   final BuildInfo buildInfo;
   final String testFilePath;
   final bool shouldCopyDillFile;
+  final TestTimeRecorder? testTimeRecorder;
 
 
   ResidentCompiler? compiler;
@@ -139,6 +143,7 @@ class TestCompiler {
       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 @@ class TestCompiler {
         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);
     }

packages/flutter_tools/lib/src/test/test_time_recorder.dart

+// 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,
+}

packages/flutter_tools/test/commands.shard/hermetic/test_test.dart

@@ -11,6 +11,7 @@ import 'package:args/command_runner.dart';
 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/device.dart';
 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 'package:meta/meta.dart';
 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 @@ final String _packageConfigContents = json.encode(<String, Object>{
 void main() {
   Cache.disableLocking();
   MemoryFileSystem fs;
+  LoggingLogger logger;
 
   setUp(() {
     fs = MemoryFileSystem.test();
@@ -70,6 +74,8 @@ void main() {
     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 @@ void main() {
   }, overrides: <Type, Generator>{
     FileSystem: () => fs,
     ProcessManager: () => FakeProcessManager.any(),
+    Logger: () => logger,
   });
 
   testUsingContext('Missing dependencies in pubspec for integration tests',
@@ -317,6 +324,58 @@ dev_dependencies:
     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 @@ dev_dependencies:
 }
 
 class FakeFlutterTestRunner implements FlutterTestRunner {
-  FakeFlutterTestRunner(this.exitCode);
+  FakeFlutterTestRunner(this.exitCode, [this.leastRunTime]);
 
   int exitCode;
+  Duration leastRunTime;
   bool lastEnableObservatoryValue;
   DebuggingOptions lastDebuggingOptionsValue;
 
@@ -768,9 +828,15 @@ class FakeFlutterTestRunner implements FlutterTestRunner {
     int totalShards,
     Device integrationTestDevice,
     String integrationTestUserIdentifier,
+    TestTimeRecorder testTimeRecorder,
   }) async {
     lastEnableObservatoryValue = enableObservatory;
     lastDebuggingOptionsValue = debuggingOptions;
+
+    if (leastRunTime != null) {
+      await Future<void>.delayed(leastRunTime);
+    }
+
     return exitCode;
   }
 }

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

@@ -8,11 +8,13 @@ import 'dart:io' show Directory, File;
 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 @@ void main() {
     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 @@ void main() {
       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() {

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

@@ -16,7 +16,6 @@ import 'package:flutter_tools/src/base/io.dart';
 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/context.dart';
 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 FakeDevFSWriter implements DevFSWriter {
   }
 }
 
-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>[];

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

@@ -11,11 +11,13 @@ import 'package:flutter_tools/src/build_info.dart';
 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 @@ final BuildInfo debugBuild = BuildInfo(
 void main() {
   late FakeResidentCompiler residentCompiler;
   late FileSystem fileSystem;
+  late LoggingLogger logger;
 
   setUp(() {
     fileSystem = MemoryFileSystem.test();
@@ -40,6 +43,7 @@ void main() {
     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 @@ void main() {
     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 @@ class FakeTestCompiler extends TestCompiler {
     super.flutterProject,
     this.residentCompiler, {
       super.precompiledDillPath,
+      super.testTimeRecorder,
     }
   );
 

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

+// 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;
+}

packages/flutter_tools/test/src/logging_logger.dart

+// 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);
+  }
+}