Add flag to print more condensed build stats
The new flag is called --experimental_stats_summary. I do not consider
this flag an incompatible change, since we don't guarantee the exact
text output on the command-line. The intent is to switch to the new
summary style and then retire the flag.
The new stats look like this:
INFO: 5,000 processes: 1,000 remote, 1,000 local, 1,000 worker, 2,000 cached
INFO: Total action wall time 100.34s
INFO: Critical path 5.22s (setup 1.34s, wall time 3.89s)
INFO: Elapsed time 8.89s (loading 2.55s, execution 6.34s)
The breakdown in the last two lines follows the idea that we want to
distinguish between useful work and 'overhead':
- For the critical path breakdown, the wall time is the sum of all wall
times of all actions on the critical path, whereas 'setup' refers to
everything other than subprocess execution wall time.
- For the elapsed time breakdown, the execution time is the time of the
execution phase (which in turn is determined by the critical path),
whereas 'loading' refers to everything other than execution.
Terminology is hard and we're already using these terms to denote
different things. Suggestions welcome.
PiperOrigin-RevId: 222231747
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java b/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
index 5b10cf0..8666ce9 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
@@ -20,6 +20,7 @@
import com.google.devtools.build.lib.actions.ActionKeyContext;
import com.google.devtools.build.lib.actions.ActionResultReceivedEvent;
import com.google.devtools.build.lib.buildtool.BuildRequest;
+import com.google.devtools.build.lib.buildtool.ExecutionFinishedEvent;
import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent;
import com.google.devtools.build.lib.buildtool.buildevent.ExecutionStartingEvent;
import com.google.devtools.build.lib.clock.BlazeClock;
@@ -48,6 +49,10 @@
private Reporter reporter;
private boolean enabled;
+ private boolean statsSummary;
+ private long commandStartMillis;
+ private long executionStartMillis;
+ private long executionEndMillis;
private SpawnStats spawnStats;
@Override
@@ -55,6 +60,7 @@
this.reporter = env.getReporter();
this.eventBus = env.getEventBus();
this.actionKeyContext = env.getSkyframeExecutor().getActionKeyContext();
+ commandStartMillis = env.getCommandStartTime();
this.spawnStats = new SpawnStats();
eventBus.register(this);
}
@@ -74,6 +80,8 @@
@Subscribe
public void executionPhaseStarting(ExecutionStartingEvent event) {
+ // TODO(ulfjack): Make sure to use the same clock as for commandStartMillis.
+ executionStartMillis = BlazeClock.instance().currentTimeMillis();
if (enabled) {
criticalPathComputer = new CriticalPathComputer(actionKeyContext, BlazeClock.instance());
eventBus.register(criticalPathComputer);
@@ -81,6 +89,11 @@
}
@Subscribe
+ public void executionPhaseFinish(@SuppressWarnings("unused") ExecutionFinishedEvent event) {
+ executionEndMillis = BlazeClock.instance().currentTimeMillis();
+ }
+
+ @Subscribe
@AllowConcurrentEvents
public void actionResultReceived(ActionResultReceivedEvent event) {
spawnStats.countActionResult(event.getActionResult());
@@ -98,11 +111,11 @@
String.format(
"%f", event.getResult().getElapsedSeconds()).getBytes(StandardCharsets.UTF_8));
+ AggregatedCriticalPath criticalPath = AggregatedCriticalPath.EMPTY;
if (criticalPathComputer != null) {
try (SilentCloseable c =
Profiler.instance().profile(ProfilerTask.CRITICAL_PATH, "Critical path")) {
- AggregatedCriticalPath criticalPath =
- criticalPathComputer.aggregate();
+ criticalPath = criticalPathComputer.aggregate();
items.add(criticalPath.toStringSummaryNoRemote());
event.getResult().getBuildToolLogCollection()
.addDirectValue(
@@ -125,10 +138,30 @@
}
}
- reporter.handle(Event.info(Joiner.on(", ").join(items)));
-
String spawnSummary = spawnStats.getSummary();
- reporter.handle(Event.info(spawnSummary));
+ if (statsSummary) {
+ reporter.handle(Event.info(spawnStats.getSummary()));
+ reporter.handle(
+ Event.info(
+ String.format(
+ "Total action wall time %.2fs", spawnStats.getTotalWallTimeMillis() / 1000.0)));
+ if (criticalPath != AggregatedCriticalPath.EMPTY) {
+ reporter.handle(Event.info(criticalPath.getNewStringSummary()));
+ }
+ long now = event.getResult().getStopTime();
+ long executionTime = executionEndMillis - executionStartMillis;
+ long overheadTime = now - commandStartMillis - executionTime;
+ reporter.handle(
+ Event.info(
+ String.format(
+ "Elapsed time %.2fs (preparation %.2fs, execution %.2fs)",
+ (now - commandStartMillis) / 1000.0,
+ overheadTime / 1000.0,
+ executionTime / 1000.0)));
+ } else {
+ reporter.handle(Event.info(Joiner.on(", ").join(items)));
+ reporter.handle(Event.info(spawnSummary));
+ }
event.getResult().getBuildToolLogCollection()
.addDirectValue("process stats", spawnSummary.getBytes(StandardCharsets.UTF_8));
