Add logging of the compile step.

Author: davidmorgan

build_runner/CHANGELOG.md

@@ -1,3 +1,8 @@
+## 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.3
 
 - Performance: improve scalability with the number of library cycles, making

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

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())

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<String> _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<String, _PhaseProgress> _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<T> logCompile<T>({
+    required bool isAot,
+    required Future<T> 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<InBuildPhase, int> 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;

build_runner/pubspec.yaml

@@ -1,5 +1,5 @@
 name: build_runner
-version: 2.10.3
+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

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);

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);

build_test/CHANGELOG.md

@@ -1,3 +1,7 @@
+## 3.5.4-wip
+
+- Use `build_runner` 2.11.0.
+
 ## 3.5.3
 
 - Use `build_runner` 2.10.3.

build_test/pubspec.yaml

@@ -10,7 +10,7 @@ environment:
 dependencies:
   build: ^4.0.0
   build_config: ^1.0.0
-  build_runner: '2.10.3'
+  build_runner: '2.11.0-wip'
   built_collection: ^5.1.1
   crypto: ^3.0.0
   glob: ^2.0.0