From b788e86f4a6d37eef1a77923cf0391e5daecda55 Mon Sep 17 00:00:00 2001 From: David Morgan Date: Mon, 27 Oct 2025 17:59:49 +0100 Subject: [PATCH] Add logging of the compile step. --- build_runner/CHANGELOG.md | 6 + .../lib/src/bootstrap/bootstrapper.dart | 7 +- .../src/bootstrap/build_process_state.dart | 14 +++ build_runner/lib/src/logging/build_log.dart | 117 +++++++++++++++++- build_runner/pubspec.yaml | 2 +- .../logging/build_log_console_mode_test.dart | 16 +++ .../logging/build_log_line_mode_test.dart | 10 ++ build_test/CHANGELOG.md | 4 + build_test/pubspec.yaml | 2 +- 9 files changed, 171 insertions(+), 7 deletions(-) diff --git a/build_runner/CHANGELOG.md b/build_runner/CHANGELOG.md index fdd2721d8..0454ab892 100644 --- a/build_runner/CHANGELOG.md +++ b/build_runner/CHANGELOG.md @@ -1,7 +1,13 @@ +## 2.11.0-wip + +- Add logging of builder compilation so you can tell how much time is spent + on the JIT or AOT compile. Explicitly log restarts to recompile builders. + ## 2.10.4 - Allow `analyzer` 9.0.0. + ## 2.10.3 - Performance: improve scalability with the number of library cycles, making diff --git a/build_runner/lib/src/bootstrap/bootstrapper.dart b/build_runner/lib/src/bootstrap/bootstrapper.dart index ab4e9e8cb..da7a19c73 100644 --- a/build_runner/lib/src/bootstrap/bootstrapper.dart +++ b/build_runner/lib/src/bootstrap/bootstrapper.dart @@ -59,7 +59,10 @@ class Bootstrapper { // Compile if there was any change. if (!_compiler.checkFreshness(digestsAreFresh: false).outputIsFresh) { - final result = await _compiler.compile(experiments: experiments); + final result = await buildLog.logCompile( + isAot: compileAot, + function: () => _compiler.compile(experiments: experiments), + ); if (!result.succeeded) { final bool failedDueToMirrors; if (result.messages == null) { @@ -109,6 +112,8 @@ class Bootstrapper { if (exitCode != ExitCode.tempFail.code) { return exitCode; } + + buildLog.nextBuild(recompilingBuilders: true); } } diff --git a/build_runner/lib/src/bootstrap/build_process_state.dart b/build_runner/lib/src/bootstrap/build_process_state.dart index d7e0ec9b3..1506efd63 100644 --- a/build_runner/lib/src/bootstrap/build_process_state.dart +++ b/build_runner/lib/src/bootstrap/build_process_state.dart @@ -45,6 +45,20 @@ class BuildProcessState { set elapsedMillis(int elapsedMillis) => _state['elapsedMillis'] = elapsedMillis; + // For `buildLog`, the JIT compile progress. + Object? get jitCompileProgress => _state['jitCompileProgress']; + set jitCompileProgress(Object? jitCompileProgress) => + _state['jitCompileProgress'] = jitCompileProgress; + + // For `buildLog`, the AOT compile progress. + Object? get aotCompileProgress => _state['aotCompileProgress']; + set aotCompileProgress(Object? aotCompileProgress) => + _state['aotCompileProgress'] = aotCompileProgress; + + // For `buildLog`, the build number. + int get buildNumber => _state['buildNumber'] as int? ?? 1; + set buildNumber(int buildNumber) => _state['buildNumber'] = buildNumber; + /// The package config URI. String get packageConfigUri => (_state['packageConfigUri'] ??= Isolate.packageConfigSync!.toString()) diff --git a/build_runner/lib/src/logging/build_log.dart b/build_runner/lib/src/logging/build_log.dart index 57a6f7344..9c65be70f 100644 --- a/build_runner/lib/src/logging/build_log.dart +++ b/build_runner/lib/src/logging/build_log.dart @@ -2,6 +2,7 @@ // for details. All rights reserved. Use of this source code is governed by a // BSD-style license that can be found in the LICENSE file. +import 'dart:async'; import 'dart:io'; import 'dart:math'; @@ -73,6 +74,12 @@ class BuildLog { /// Errors logged. final ListBuilder _errors = ListBuilder(); + /// JIT compile progress, if there was a JIT compile. + _CompileProgress? _jitCompileProgress; + + /// AOT compile progress, if there was an AOT compile. + _CompileProgress? _aotCompileProgress; + /// Progress by build phase. final Map _phaseProgress = {}; @@ -102,6 +109,9 @@ class BuildLog { buildProcessState.doBeforeSend(() { buildProcessState.elapsedMillis = _processDuration.inMilliseconds; buildProcessState.buildLogMode = configuration.mode; + buildProcessState.jitCompileProgress = _jitCompileProgress?.serialize(); + buildProcessState.aotCompileProgress = _aotCompileProgress?.serialize(); + buildProcessState.buildNumber = _buildNumber; }); void updateFromProcessState() { _processDuration = Duration( @@ -110,6 +120,13 @@ class BuildLog { configuration = configuration.rebuild((b) { b.mode = buildProcessState.buildLogMode; }); + _jitCompileProgress = _CompileProgress.deserialize( + buildProcessState.jitCompileProgress, + ); + _aotCompileProgress = _CompileProgress.deserialize( + buildProcessState.aotCompileProgress, + ); + _buildNumber = buildProcessState.buildNumber; } updateFromProcessState(); @@ -226,6 +243,59 @@ class BuildLog { ); } + Future logCompile({ + required bool isAot, + required Future Function() function, + }) async { + final progress = _CompileProgress(); + if (isAot) { + _aotCompileProgress = progress; + } else { + _jitCompileProgress = progress; + } + _compileTick(isAot: isAot, firstTick: true, lastTick: false); + + final timer = Timer.periodic( + const Duration(milliseconds: 100), + (_) => _compileTick(isAot: isAot, firstTick: false, lastTick: false), + ); + try { + return await function(); + } finally { + timer.cancel(); + _compileTick(isAot: isAot, firstTick: false, lastTick: true); + } + } + + void _compileTick({ + required bool isAot, + required bool firstTick, + required bool lastTick, + }) { + final duration = _stopwatch.elapsed; + _stopwatch.reset(); + _processDuration += duration; + + if (!firstTick) { + if (isAot) { + _aotCompileProgress!.duration += duration; + } else { + _jitCompileProgress!.duration += duration; + } + } + + if (_shouldShowProgressNow || lastTick) { + if (_display.displayingBlocks) { + _display.block(render()); + } else { + _display.message( + Severity.info, + _renderCompiling(isAot: isAot).toString(), + ); + } + } + } + /// Sets up logging of build phases with the number of primary inputs matching /// for each required phase. void startPhases(Map primaryInputCountsByPhase) { @@ -337,13 +407,16 @@ class BuildLog { /// build) has started. /// /// Clears timings and messages. - void nextBuild() { + void nextBuild({bool recompilingBuilders = false}) { _stopwatch.reset(); _processDuration = Duration.zero; activities.clear(); _messages.clear(); _status.clear(); - _display.flushAndPrint('\nStarting build #${++_buildNumber}.\n'); + _display.flushAndPrint( + '\nStarting build #${++_buildNumber}' + '${recompilingBuilders ? ' with updated builders' : ''}.\n', + ); } /// Logs that the build has finished with [result] and the count of [outputs]. @@ -374,6 +447,10 @@ class BuildLog { ); } + _processDuration = Duration.zero; + _jitCompileProgress = null; + _aotCompileProgress = null; + final errors = _errors.build(); _errors.clear(); return errors; @@ -442,6 +519,13 @@ class BuildLog { AnsiBuffer render() { final result = AnsiBuffer(); + if (_jitCompileProgress != null) { + result.write(_renderCompiling(isAot: false)); + } + if (_aotCompileProgress != null) { + result.write(_renderCompiling(isAot: true)); + } + final displayedProgressEntries = _phaseProgress.entries.where( (e) => e.value.isDisplayed || _messages.hasMessages(phaseName: e.key), ); @@ -484,8 +568,20 @@ class BuildLog { return result; } + AnsiBufferLine _renderCompiling({required bool isAot}) { + final progress = isAot ? _aotCompileProgress! : _jitCompileProgress!; + return AnsiBufferLine([ + renderDuration(progress.duration), + ' ', + AnsiBuffer.bold, + 'compiling builders', + AnsiBuffer.reset, + '/${isAot ? 'aot' : 'jit'}', + ]); + } + /// Renders a line describing the progress of [phaseName]. - AnsiBufferLine _renderPhase(String phaseName, {int padDuration = 0}) { + AnsiBufferLine _renderPhase(String phaseName) { final activities = this.activities.render(phaseName: phaseName); var firstSeparator = true; @@ -499,7 +595,7 @@ class BuildLog { final progress = _phaseProgress[phaseName]!; return AnsiBufferLine([ - renderDuration(progress.duration).padLeft(padDuration), + renderDuration(progress.duration), ' ', AnsiBuffer.bold, phaseName, @@ -554,6 +650,19 @@ extension _PhaseExtension on InBuildPhase { lazy ? '$displayName (lazy)' : displayName; } +/// Compile progress. +class _CompileProgress { + Duration duration = Duration.zero; + + Object? serialize() => duration.inMilliseconds; + + static _CompileProgress? deserialize(Object? serialized) { + if (serialized == null) return null; + return _CompileProgress() + ..duration = Duration(milliseconds: serialized as int); + } +} + /// Progress metrics tracked for each build phase. class _PhaseProgress { Duration duration = Duration.zero; diff --git a/build_runner/pubspec.yaml b/build_runner/pubspec.yaml index fb3f6377a..930ec69de 100644 --- a/build_runner/pubspec.yaml +++ b/build_runner/pubspec.yaml @@ -1,5 +1,5 @@ name: build_runner -version: 2.10.4 +version: 2.11.0-wip description: A build system for Dart code generation and modular compilation. repository: https://github.com/dart-lang/build/tree/master/build_runner resolution: workspace diff --git a/build_runner/test/logging/build_log_console_mode_test.dart b/build_runner/test/logging/build_log_console_mode_test.dart index 8acd55e5e..01bffb803 100644 --- a/build_runner/test/logging/build_log_console_mode_test.dart +++ b/build_runner/test/logging/build_log_console_mode_test.dart @@ -44,6 +44,22 @@ E An error.'''), ); }); + test('compile progress', () { + buildLog.logCompile(isAot: false, function: () async {}); + expect( + render(), + padLinesRight(''' +0s compiling builders/jit'''), + ); + buildLog.logCompile(isAot: true, function: () async {}); + expect( + render(), + padLinesRight(''' +0s compiling builders/jit +0s compiling builders/aot'''), + ); + }); + test('phase progress', () { final phases = _createPhases({'builder1': 10, 'builder2': 15}); buildLog.startPhases(phases); diff --git a/build_runner/test/logging/build_log_line_mode_test.dart b/build_runner/test/logging/build_log_line_mode_test.dart index 507d102dc..d5ce56e1e 100644 --- a/build_runner/test/logging/build_log_line_mode_test.dart +++ b/build_runner/test/logging/build_log_line_mode_test.dart @@ -37,6 +37,16 @@ void main() { ]); }); + test('compile progress', () { + buildLog.logCompile(isAot: false, function: () async {}); + expect(lines, [' 0s compiling builders/jit']); + buildLog.logCompile(isAot: true, function: () async {}); + expect(lines, [ + ' 0s compiling builders/jit', + ' 0s compiling builders/aot', + ]); + }); + test('phase progress', () { final phases = _createPhases({'builder1': 10, 'builder2': 15}); buildLog.startPhases(phases); diff --git a/build_test/CHANGELOG.md b/build_test/CHANGELOG.md index 9dac8611b..0b87bc9d4 100644 --- a/build_test/CHANGELOG.md +++ b/build_test/CHANGELOG.md @@ -1,3 +1,7 @@ +## 3.5.5-wip + +- Use `build_runner` 2.11.0. + ## 3.5.4 - Use `build_runner` 2.10.4. diff --git a/build_test/pubspec.yaml b/build_test/pubspec.yaml index cecb4a45c..0b15ef0b5 100644 --- a/build_test/pubspec.yaml +++ b/build_test/pubspec.yaml @@ -10,7 +10,7 @@ environment: dependencies: build: ^4.0.0 build_config: ^1.0.0 - build_runner: '2.10.4' + build_runner: '2.11.0-wip' built_collection: ^5.1.1 crypto: ^3.0.0 glob: ^2.0.0