[flutter_plugin_tools] Add optional timing info (#4500)

Adds a `--log-timing` flag that can be passed to cause package-looping
commands to log relative start time and per-package elapsed time, to
help with future efforts to improve CI times (e.g., finding unusually
slow packages, or designing changes to sharding).

Adds this flag to the CI scripts to enable timing there.

script/tool/CHANGELOG.md

@@ -1,3 +1,8 @@
+## NEXT
+
+- Added `--log-timing` to add timing information to package headers in looping
+  commands.
+
 ## 0.7.2
 
 - Update Firebase Testlab deprecated test device. (Pixel 4 API 29 -> Pixel 5 API 30).

script/tool/lib/src/common/package_looping_command.dart

@@ -170,7 +170,7 @@ abstract class PackageLoopingCommand extends PluginCommand {
   /// messages. DO NOT RELY on someone noticing a warning; instead, use it for
   /// things that might be useful to someone debugging an unexpected result.
   void logWarning(String warningMessage) {
-    print(Colorize(warningMessage)..yellow());
+    _printColorized(warningMessage, Styles.YELLOW);
     if (_currentPackageEntry != null) {
       _packagesWithWarnings.add(_currentPackageEntry!);
     } else {
@@ -219,6 +219,8 @@ abstract class PackageLoopingCommand extends PluginCommand {
     _otherWarningCount = 0;
     _currentPackageEntry = null;
 
+    final DateTime runStart = DateTime.now();
+
     await initializeRun();
 
     final List<PackageEnumerationEntry> targetPackages =
@@ -227,8 +229,9 @@ abstract class PackageLoopingCommand extends PluginCommand {
     final Map<PackageEnumerationEntry, PackageResult> results =
         <PackageEnumerationEntry, PackageResult>{};
     for (final PackageEnumerationEntry entry in targetPackages) {
+      final DateTime packageStart = DateTime.now();
       _currentPackageEntry = entry;
-      _printPackageHeading(entry);
+      _printPackageHeading(entry, startTime: runStart);
 
       // Command implementations should never see excluded packages; they are
       // included at this level only for logging.
@@ -246,11 +249,20 @@ abstract class PackageLoopingCommand extends PluginCommand {
         result = PackageResult.fail(<String>['Unhandled exception']);
       }
       if (result.state == RunState.skipped) {
-        final String message =
-            '${indentation}SKIPPING: ${result.details.first}';
-        captureOutput ? print(message) : print(Colorize(message)..darkGray());
+        _printColorized('${indentation}SKIPPING: ${result.details.first}',
+            Styles.DARK_GRAY);
       }
       results[entry] = result;
+
+      // Only log an elapsed time for long output; for short output, comparing
+      // the relative timestamps of successive entries should be trivial.
+      if (shouldLogTiming && hasLongOutput) {
+        final Duration elapsedTime = DateTime.now().difference(packageStart);
+        _printColorized(
+            '\n[${entry.package.displayName} completed in '
+            '${elapsedTime.inMinutes}m ${elapsedTime.inSeconds % 60}s]',
+            Styles.DARK_GRAY);
+      }
     }
     _currentPackageEntry = null;
 
@@ -287,11 +299,20 @@ abstract class PackageLoopingCommand extends PluginCommand {
   /// Something is always printed to make it easier to distinguish between
   /// a command running for a package and producing no output, and a command
   /// not having been run for a package.
-  void _printPackageHeading(PackageEnumerationEntry entry) {
+  void _printPackageHeading(PackageEnumerationEntry entry,
+      {required DateTime startTime}) {
     final String packageDisplayName = entry.package.displayName;
     String heading = entry.excluded
         ? 'Not running for $packageDisplayName; excluded'
         : 'Running for $packageDisplayName';
+
+    if (shouldLogTiming) {
+      final Duration relativeTime = DateTime.now().difference(startTime);
+      final String timeString = _formatDurationAsRelativeTime(relativeTime);
+      heading =
+          hasLongOutput ? '$heading [@$timeString]' : '[$timeString] $heading';
+    }
+
     if (hasLongOutput) {
       heading = '''
 
@@ -302,13 +323,7 @@ abstract class PackageLoopingCommand extends PluginCommand {
     } else if (!entry.excluded) {
       heading = '$heading...';
     }
-    if (captureOutput) {
-      print(heading);
-    } else {
-      final Colorize colorizeHeading = Colorize(heading);
-      print(
-          entry.excluded ? colorizeHeading.darkGray() : colorizeHeading.cyan());
-    }
+    _printColorized(heading, entry.excluded ? Styles.DARK_GRAY : Styles.CYAN);
   }
 
   /// Prints a summary of packges run, packages skipped, and warnings.
@@ -401,4 +416,21 @@ abstract class PackageLoopingCommand extends PluginCommand {
     }
     _printError(failureListFooter);
   }
+
+  /// Prints [message] in [color] unless [captureOutput] is set, in which case
+  /// it is printed without color.
+  void _printColorized(String message, Styles color) {
+    if (captureOutput) {
+      print(message);
+    } else {
+      print(Colorize(message)..apply(color));
+    }
+  }
+
+  /// Returns a duration [d] formatted as minutes:seconds. Does not use hours,
+  /// since time logging is primarily intended for CI, where durations should
+  /// always be less than an hour.
+  String _formatDurationAsRelativeTime(Duration d) {
+    return '${d.inMinutes}:${(d.inSeconds % 60).toString().padLeft(2, '0')}';
+  }
 }

script/tool/lib/src/common/plugin_command.dart

@@ -76,7 +76,7 @@ abstract class PluginCommand extends Command<void> {
             'If no packages have changed, or if there have been changes that may\n'
             'affect all packages, the command runs on all packages.\n'
             'The packages excluded with $_excludeArg is also excluded even if changed.\n'
-            'See $_kBaseSha if a custom base is needed to determine the diff.\n\n'
+            'See $_baseShaArg if a custom base is needed to determine the diff.\n\n'
             'Cannot be combined with $_packagesArg.\n');
     argParser.addFlag(_packagesForBranchArg,
         help:
@@ -86,20 +86,25 @@ abstract class PluginCommand extends Command<void> {
             'Cannot be combined with $_packagesArg.\n\n'
             'This is intended for use in CI.\n',
         hide: true);
-    argParser.addOption(_kBaseSha,
+    argParser.addOption(_baseShaArg,
         help: 'The base sha used to determine git diff. \n'
             'This is useful when $_runOnChangedPackagesArg is specified.\n'
             'If not specified, merge-base is used as base sha.');
+    argParser.addFlag(_logTimingArg,
+        help: 'Logs timing information.\n\n'
+            'Currently only logs per-package timing for multi-package commands, '
+            'but more information may be added in the future.');
   }
 
-  static const String _pluginsArg = 'plugins';
-  static const String _packagesArg = 'packages';
-  static const String _shardIndexArg = 'shardIndex';
-  static const String _shardCountArg = 'shardCount';
+  static const String _baseShaArg = 'base-sha';
   static const String _excludeArg = 'exclude';
-  static const String _runOnChangedPackagesArg = 'run-on-changed-packages';
+  static const String _logTimingArg = 'log-timing';
+  static const String _packagesArg = 'packages';
   static const String _packagesForBranchArg = 'packages-for-branch';
-  static const String _kBaseSha = 'base-sha';
+  static const String _pluginsArg = 'plugins';
+  static const String _runOnChangedPackagesArg = 'run-on-changed-packages';
+  static const String _shardCountArg = 'shardCount';
+  static const String _shardIndexArg = 'shardIndex';
 
   /// The directory containing the plugin packages.
   final Directory packagesDir;
@@ -183,6 +188,11 @@ abstract class PluginCommand extends Command<void> {
     return (argResults![key] as List<String>?) ?? <String>[];
   }
 
+  /// If true, commands should log timing information that might be useful in
+  /// analyzing their runtime (e.g., the per-package time for multi-package
+  /// commands).
+  bool get shouldLogTiming => getBoolArg(_logTimingArg);
+
   void _checkSharding() {
     final int? shardIndex = int.tryParse(getStringArg(_shardIndexArg));
     final int? shardCount = int.tryParse(getStringArg(_shardCountArg));
@@ -411,11 +421,11 @@ abstract class PluginCommand extends Command<void> {
     return entity is Directory && entity.childFile('pubspec.yaml').existsSync();
   }
 
-  /// Retrieve an instance of [GitVersionFinder] based on `_kBaseSha` and [gitDir].
+  /// Retrieve an instance of [GitVersionFinder] based on `_baseShaArg` and [gitDir].
   ///
   /// Throws tool exit if [gitDir] nor root directory is a git directory.
   Future<GitVersionFinder> retrieveVersionFinder() async {
-    final String baseSha = getStringArg(_kBaseSha);
+    final String baseSha = getStringArg(_baseShaArg);
 
     final GitVersionFinder gitVersionFinder =
         GitVersionFinder(await gitDir, baseSha);

script/tool/test/common/package_looping_command_test.dart

@@ -22,6 +22,7 @@ import '../util.dart';
 import 'plugin_command_test.mocks.dart';
 
 // Constants for colorized output start and end.
+const String _startElapsedTimeColor = '\x1B[90m';
 const String _startErrorColor = '\x1B[31m';
 const String _startHeadingColor = '\x1B[36m';
 const String _startSkipColor = '\x1B[90m';
@@ -272,6 +273,46 @@ void main() {
           ]));
     });
 
+    test('prints timing info in long-form output when requested', () async {
+      createFakePlugin('package_a', packagesDir);
+      createFakePackage('package_b', packagesDir);
+
+      final TestPackageLoopingCommand command =
+          createTestCommand(hasLongOutput: true);
+      final List<String> output =
+          await runCommand(command, arguments: <String>['--log-timing']);
+
+      const String separator =
+          '============================================================';
+      expect(
+          output,
+          containsAllInOrder(<String>[
+            '$_startHeadingColor\n$separator\n|| Running for package_a [@0:00]\n$separator\n$_endColor',
+            '$_startElapsedTimeColor\n[package_a completed in 0m 0s]$_endColor',
+            '$_startHeadingColor\n$separator\n|| Running for package_b [@0:00]\n$separator\n$_endColor',
+            '$_startElapsedTimeColor\n[package_b completed in 0m 0s]$_endColor',
+          ]));
+    });
+
+    test('prints timing info in short-form output when requested', () async {
+      createFakePlugin('package_a', packagesDir);
+      createFakePackage('package_b', packagesDir);
+
+      final TestPackageLoopingCommand command =
+          createTestCommand(hasLongOutput: false);
+      final List<String> output =
+          await runCommand(command, arguments: <String>['--log-timing']);
+
+      expect(
+          output,
+          containsAllInOrder(<String>[
+            '$_startHeadingColor[0:00] Running for package_a...$_endColor',
+            '$_startHeadingColor[0:00] Running for package_b...$_endColor',
+          ]));
+      // Short-form output should not include elapsed time.
+      expect(output, isNot(contains('[package_a completed in 0m 0s]')));
+    });
+
     test('shows the success message when nothing fails', () async {
       createFakePackage('package_a', packagesDir);
       createFakePackage('package_b', packagesDir);