[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.
diff --git a/.ci/scripts/build_examples_uwp.sh b/.ci/scripts/build_examples_uwp.sh
index 639cb05..04b8256 100644
--- a/.ci/scripts/build_examples_uwp.sh
+++ b/.ci/scripts/build_examples_uwp.sh
@@ -4,4 +4,4 @@
# found in the LICENSE file.
dart ./script/tool/bin/flutter_plugin_tools.dart build-examples --winuwp \
- --packages-for-branch
+ --packages-for-branch --log-timing
diff --git a/.ci/scripts/build_examples_win32.sh b/.ci/scripts/build_examples_win32.sh
index 8c090f4..bcf57a4 100644
--- a/.ci/scripts/build_examples_win32.sh
+++ b/.ci/scripts/build_examples_win32.sh
@@ -4,4 +4,4 @@
# found in the LICENSE file.
dart ./script/tool/bin/flutter_plugin_tools.dart build-examples --windows \
- --packages-for-branch
+ --packages-for-branch --log-timing
diff --git a/.ci/scripts/drive_examples_win32.sh b/.ci/scripts/drive_examples_win32.sh
index 63abc06..67f4fde 100644
--- a/.ci/scripts/drive_examples_win32.sh
+++ b/.ci/scripts/drive_examples_win32.sh
@@ -4,4 +4,4 @@
# found in the LICENSE file.
dart ./script/tool/bin/flutter_plugin_tools.dart drive-examples --windows \
- --packages-for-branch
+ --packages-for-branch --log-timing
diff --git a/.ci/scripts/native_test_win32.sh b/.ci/scripts/native_test_win32.sh
index 9385157..37cf54e 100644
--- a/.ci/scripts/native_test_win32.sh
+++ b/.ci/scripts/native_test_win32.sh
@@ -4,4 +4,4 @@
# found in the LICENSE file.
dart ./script/tool/bin/flutter_plugin_tools.dart native-test --windows \
- --no-integration --packages-for-branch
+ --no-integration --packages-for-branch --log-timing
diff --git a/script/tool/CHANGELOG.md b/script/tool/CHANGELOG.md
index aa93139..5a037c8 100644
--- a/script/tool/CHANGELOG.md
+++ b/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).
diff --git a/script/tool/lib/src/common/package_looping_command.dart b/script/tool/lib/src/common/package_looping_command.dart
index 973ac99..bfee71a 100644
--- a/script/tool/lib/src/common/package_looping_command.dart
+++ b/script/tool/lib/src/common/package_looping_command.dart
@@ -170,7 +170,7 @@
/// 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 @@
_otherWarningCount = 0;
_currentPackageEntry = null;
+ final DateTime runStart = DateTime.now();
+
await initializeRun();
final List<PackageEnumerationEntry> targetPackages =
@@ -227,8 +229,9 @@
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 @@
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 @@
/// 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 @@
} 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 @@
}
_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')}';
+ }
}
diff --git a/script/tool/lib/src/common/plugin_command.dart b/script/tool/lib/src/common/plugin_command.dart
index 6708f91..f40a102 100644
--- a/script/tool/lib/src/common/plugin_command.dart
+++ b/script/tool/lib/src/common/plugin_command.dart
@@ -76,7 +76,7 @@
'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 @@
'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 @@
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 @@
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);
diff --git a/script/tool/test/common/package_looping_command_test.dart b/script/tool/test/common/package_looping_command_test.dart
index 7cf0396..6e46a33 100644
--- a/script/tool/test/common/package_looping_command_test.dart
+++ b/script/tool/test/common/package_looping_command_test.dart
@@ -22,6 +22,7 @@
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 @@
]));
});
+ 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);
diff --git a/script/tool_runner.sh b/script/tool_runner.sh
index 99bab38..6618154 100755
--- a/script/tool_runner.sh
+++ b/script/tool_runner.sh
@@ -19,4 +19,4 @@
# The tool expects to be run from the repo root.
cd "$REPO_DIR"
# Run from the in-tree source.
-dart run "$TOOL_PATH" "$@" --packages-for-branch $PLUGIN_SHARDING
+dart run "$TOOL_PATH" "$@" --packages-for-branch --log-timing $PLUGIN_SHARDING
