Add finish time in events which are used to compute critical path.
Before that change we used clock to compute finish time in `CriticalPathComputer` for events `ActionMiddlemanEvent`, `CachedActionEvent`, `ActionCompletionEvent`. This time could be different from real finish time because subscribers execute their code serially. So it could be delay between real action completion and event processing.
PiperOrigin-RevId: 540248815
Change-Id: Ie6cb701b135ac3b4cd3edb6be5251e30edbb4823
diff --git a/src/main/java/com/google/devtools/build/lib/actions/ActionCompletionEvent.java b/src/main/java/com/google/devtools/build/lib/actions/ActionCompletionEvent.java
index f0c4c78..8086518 100644
--- a/src/main/java/com/google/devtools/build/lib/actions/ActionCompletionEvent.java
+++ b/src/main/java/com/google/devtools/build/lib/actions/ActionCompletionEvent.java
@@ -19,13 +19,18 @@
/** An event that is fired after an action completes (either successfully or not). */
public final class ActionCompletionEvent implements Postable {
- private final long relativeActionStartTime;
+ private final long relativeActionStartTimeNanos;
+ private final long finishTimeNanos;
private final Action action;
private final ActionLookupData actionLookupData;
public ActionCompletionEvent(
- long relativeActionStartTime, Action action, ActionLookupData actionLookupData) {
- this.relativeActionStartTime = relativeActionStartTime;
+ long relativeActionStartTimeNanos,
+ long finishTimeNanos,
+ Action action,
+ ActionLookupData actionLookupData) {
+ this.relativeActionStartTimeNanos = relativeActionStartTimeNanos;
+ this.finishTimeNanos = finishTimeNanos;
this.action = action;
this.actionLookupData = actionLookupData;
}
@@ -37,8 +42,12 @@
return action;
}
- public long getRelativeActionStartTime() {
- return relativeActionStartTime;
+ public long getRelativeActionStartTimeNanos() {
+ return relativeActionStartTimeNanos;
+ }
+
+ public long getFinishTimeNanos() {
+ return finishTimeNanos;
}
public ActionLookupData getActionLookupData() {
@@ -48,7 +57,8 @@
@Override
public String toString() {
return MoreObjects.toStringHelper("ActionCompletionEvent")
- .add("relativeActionStartTime", relativeActionStartTime)
+ .add("relativeActionStartTimeNanos", relativeActionStartTimeNanos)
+ .add("finishTimeNanos", finishTimeNanos)
.add("action", action)
.add("actionLookupData", actionLookupData)
.toString();
diff --git a/src/main/java/com/google/devtools/build/lib/actions/ActionMiddlemanEvent.java b/src/main/java/com/google/devtools/build/lib/actions/ActionMiddlemanEvent.java
index a27d0c6..52613e0 100644
--- a/src/main/java/com/google/devtools/build/lib/actions/ActionMiddlemanEvent.java
+++ b/src/main/java/com/google/devtools/build/lib/actions/ActionMiddlemanEvent.java
@@ -25,20 +25,22 @@
private final Action action;
private final long nanoTimeStart;
+ private final long nanoTimeFinish;
/**
* Create an event for action that has been started.
*
* @param action the middleman action.
* @param nanoTimeStart the time when the action was started. This allow us to record more
- * accurately the time spent by the middleman action, since even for middleman actions we execute
- * some.
+ * accurately the time spent by the middleman action, since even for middleman actions we
+ * execute some.
*/
- public ActionMiddlemanEvent(Action action, long nanoTimeStart) {
+ public ActionMiddlemanEvent(Action action, long nanoTimeStart, long nanoTimeFinish) {
Preconditions.checkArgument(action.getActionType().isMiddleman(),
"Only middleman actions should be passed: %s", action);
this.action = action;
this.nanoTimeStart = nanoTimeStart;
+ this.nanoTimeFinish = nanoTimeFinish;
}
/**
@@ -52,4 +54,7 @@
return nanoTimeStart;
}
+ public long getNanoTimeFinish() {
+ return nanoTimeFinish;
+ }
}
diff --git a/src/main/java/com/google/devtools/build/lib/actions/CachedActionEvent.java b/src/main/java/com/google/devtools/build/lib/actions/CachedActionEvent.java
index 28318e0..ce5bac6 100644
--- a/src/main/java/com/google/devtools/build/lib/actions/CachedActionEvent.java
+++ b/src/main/java/com/google/devtools/build/lib/actions/CachedActionEvent.java
@@ -21,18 +21,20 @@
private final Action action;
private final long nanoTimeStart;
+ private final long nanoTimeFinish;
/**
* Create an event for an action that was cached.
*
* @param action the cached action
- * @param nanoTimeStart the time when the action was started. This allow us to
- * record more accurately the time spend by the action, since we execute some code before
- * deciding if we execute the action or not.
+ * @param nanoTimeStart the time when the action was started. This allow us to record more
+ * accurately the time spend by the action, since we execute some code before deciding if we
+ * execute the action or not.
*/
- public CachedActionEvent(Action action, long nanoTimeStart) {
+ public CachedActionEvent(Action action, long nanoTimeStart, long nanoTimeFinish) {
this.action = action;
this.nanoTimeStart = nanoTimeStart;
+ this.nanoTimeFinish = nanoTimeFinish;
}
public Action getAction() {
@@ -42,4 +44,8 @@
public long getNanoTimeStart() {
return nanoTimeStart;
}
+
+ public long getNanoTimeFinish() {
+ return nanoTimeFinish;
+ }
}
diff --git a/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java b/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java
index 9e75fb2..86328fd 100644
--- a/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java
+++ b/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java
@@ -230,7 +230,7 @@
ActionStats actionStats =
actionStatsMap.computeIfAbsent(event.getAction().getMnemonic(), ActionStats::new);
actionStats.numActions.incrementAndGet();
- actionStats.firstStarted.accumulate(event.getRelativeActionStartTime());
+ actionStats.firstStarted.accumulate(event.getRelativeActionStartTimeNanos());
actionStats.lastEnded.accumulate(BlazeClock.nanoTime());
spawnStats.incrementActionCount();
}
diff --git a/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComputer.java b/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComputer.java
index f9f8464..6e5ad22 100644
--- a/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComputer.java
+++ b/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComputer.java
@@ -36,7 +36,6 @@
import com.google.devtools.build.lib.actions.SpawnExecutedEvent;
import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
-import com.google.devtools.build.lib.clock.Clock;
import com.google.devtools.build.lib.skyframe.rewinding.ActionRewoundEvent;
import java.time.Duration;
import java.util.Comparator;
@@ -81,11 +80,8 @@
/** Maximum critical path found. */
private final AtomicReference<CriticalPathComponent> maxCriticalPath = new AtomicReference<>();
- private final Clock clock;
-
- public CriticalPathComputer(ActionKeyContext actionKeyContext, Clock clock) {
+ public CriticalPathComputer(ActionKeyContext actionKeyContext) {
this.actionKeyContext = actionKeyContext;
- this.clock = clock;
}
/**
@@ -251,7 +247,8 @@
Action action = event.getAction();
CriticalPathComponent component =
tryAddComponent(createComponent(action, event.getNanoTimeStart()));
- finalizeActionStat(event.getNanoTimeStart(), action, component, "middleman action");
+ finalizeActionStat(
+ event.getNanoTimeStart(), event.getNanoTimeFinish(), action, component, "middleman action");
}
/**
@@ -312,7 +309,8 @@
Action action = event.getAction();
CriticalPathComponent component =
tryAddComponent(createComponent(action, event.getNanoTimeStart()));
- finalizeActionStat(event.getNanoTimeStart(), action, component, "action cache hit");
+ finalizeActionStat(
+ event.getNanoTimeStart(), event.getNanoTimeFinish(), action, component, "action cache hit");
}
/**
@@ -326,7 +324,8 @@
CriticalPathComponent component =
Preconditions.checkNotNull(
outputArtifactToComponent.get(action.getPrimaryOutput()), action);
- finalizeActionStat(event.getRelativeActionStartTime(), action, component, "");
+ finalizeActionStat(
+ event.getRelativeActionStartTimeNanos(), event.getFinishTimeNanos(), action, component, "");
}
/**
@@ -340,7 +339,9 @@
CriticalPathComponent component =
Preconditions.checkNotNull(outputArtifactToComponent.get(action.getPrimaryOutput()));
component.finishActionExecution(
- event.getRelativeActionStartTime(), clock.nanoTime(), "action rewound");
+ event.getRelativeActionStartTimeNanos(),
+ event.getRelativeActionFinishTimeNanos(),
+ "action rewound");
}
/** Maximum critical path component found during the build. */
@@ -349,8 +350,11 @@
}
private void finalizeActionStat(
- long startTimeNanos, Action action, CriticalPathComponent component, String finalizeReason) {
- long finishTimeNanos = clock.nanoTime();
+ long startTimeNanos,
+ long finishTimeNanos,
+ Action action,
+ CriticalPathComponent component,
+ String finalizeReason) {
for (Artifact input : action.getInputs().toList()) {
addArtifactDependency(component, input, finishTimeNanos);
}
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 9a1fc76..74301d1 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
@@ -92,7 +92,7 @@
enabled = env.getOptions().getOptions(ExecutionOptions.class).enableCriticalPathProfiling;
statsSummary = env.getOptions().getOptions(ExecutionOptions.class).statsSummary;
if (enabled) {
- criticalPathComputer = new CriticalPathComputer(actionKeyContext, BlazeClock.instance());
+ criticalPathComputer = new CriticalPathComputer(actionKeyContext);
eventBus.register(criticalPathComputer);
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java b/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java
index 02fc322..658083d 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java
@@ -320,8 +320,9 @@
@Subscribe
@AllowConcurrentEvents
public void actionComplete(ActionCompletionEvent event) {
+ // TODO(vanja): handle finish time in ActionCompletionEvent
if (options.logMissedActions) {
- actionEvent(event.getAction(), event.getRelativeActionStartTime());
+ actionEvent(event.getAction(), event.getRelativeActionStartTimeNanos());
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/ActionExecutionFunction.java b/src/main/java/com/google/devtools/build/lib/skyframe/ActionExecutionFunction.java
index 0d078be..1fe0c2f 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/ActionExecutionFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/ActionExecutionFunction.java
@@ -420,7 +420,7 @@
LostInputsActionExecutionException e,
ActionLookupData actionLookupData,
Action action,
- long actionStartTime,
+ long actionStartTimeNanos,
Environment env,
NestedSet<Artifact> allInputs,
Iterable<SkyKey> depKeys,
@@ -483,7 +483,8 @@
}
if (e.isActionStartedEventAlreadyEmitted()) {
- env.getListener().post(new ActionRewoundEvent(actionStartTime, action));
+ env.getListener()
+ .post(new ActionRewoundEvent(actionStartTimeNanos, BlazeClock.nanoTime(), action));
}
skyframeActionExecutor.resetRewindingAction(actionLookupData, action, lostDiscoveredInputs);
for (Action actionToRestart : rewindPlan.getAdditionalActionsToRestart()) {
@@ -496,7 +497,9 @@
// ActionCompletionEvent because it hoped rewinding would fix things. Because it won't, this
// must emit one to compensate.
env.getListener()
- .post(new ActionCompletionEvent(actionStartTime, action, actionLookupData));
+ .post(
+ new ActionCompletionEvent(
+ actionStartTimeNanos, BlazeClock.nanoTime(), action, actionLookupData));
}
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
index 5d70ff3..f15cd79 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
@@ -79,6 +79,7 @@
import com.google.devtools.build.lib.bugreport.BugReport;
import com.google.devtools.build.lib.buildeventstream.BuildEventProtocolOptions;
import com.google.devtools.build.lib.buildtool.BuildRequestOptions;
+import com.google.devtools.build.lib.clock.BlazeClock;
import com.google.devtools.build.lib.cmdline.Label;
import com.google.devtools.build.lib.collect.nestedset.NestedSet;
import com.google.devtools.build.lib.events.Event;
@@ -673,7 +674,8 @@
boolean eventPosted = false;
// Notify BlazeRuntimeStatistics about the action middleman 'execution'.
if (action.getActionType().isMiddleman()) {
- eventHandler.post(new ActionMiddlemanEvent(action, actionStartTime));
+ eventHandler.post(
+ new ActionMiddlemanEvent(action, actionStartTime, BlazeClock.nanoTime()));
eventPosted = true;
}
@@ -723,7 +725,7 @@
/* filesetOutputSymlinksForMetrics= */ null,
/* isActionCacheHitForMetrics= */ true);
if (!eventPosted) {
- eventHandler.post(new CachedActionEvent(action, actionStartTime));
+ eventHandler.post(new CachedActionEvent(action, actionStartTime, BlazeClock.nanoTime()));
}
}
} catch (UserExecException e) {
@@ -953,7 +955,7 @@
private final class ActionRunner extends ActionStep {
private final Action action;
private final ActionMetadataHandler metadataHandler;
- private final long actionStartTime;
+ private final long actionStartTimeNanos;
private final ActionExecutionContext actionExecutionContext;
private final ActionLookupData actionLookupData;
@Nullable private final ActionExecutionStatusReporter statusReporter;
@@ -962,13 +964,13 @@
ActionRunner(
Action action,
ActionMetadataHandler metadataHandler,
- long actionStartTime,
+ long actionStartTimeNanos,
ActionExecutionContext actionExecutionContext,
ActionLookupData actionLookupData,
ActionPostprocessing postprocessing) {
this.action = action;
this.metadataHandler = metadataHandler;
- this.actionStartTime = actionStartTime;
+ this.actionStartTimeNanos = actionStartTimeNanos;
this.actionExecutionContext = actionExecutionContext;
this.actionLookupData = actionLookupData;
this.statusReporter = statusReporterRef.get();
@@ -1008,7 +1010,7 @@
boolean lostInputs = false;
try {
- ActionStartedEvent event = new ActionStartedEvent(action, actionStartTime);
+ ActionStartedEvent event = new ActionStartedEvent(action, actionStartTimeNanos);
if (statusReporter != null) {
statusReporter.updateStatus(event);
}
@@ -1074,7 +1076,9 @@
statusReporter.remove(action);
}
if (postActionCompletionEvent) {
- eventHandler.post(new ActionCompletionEvent(actionStartTime, action, actionLookupData));
+ eventHandler.post(
+ new ActionCompletionEvent(
+ actionStartTimeNanos, BlazeClock.nanoTime(), action, actionLookupData));
}
String message = action.getProgressMessage();
if (message != null) {
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/rewinding/ActionRewoundEvent.java b/src/main/java/com/google/devtools/build/lib/skyframe/rewinding/ActionRewoundEvent.java
index fe0ac35..8eb5b7f 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/rewinding/ActionRewoundEvent.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/rewinding/ActionRewoundEvent.java
@@ -22,7 +22,8 @@
*/
public final class ActionRewoundEvent implements Postable {
- private final long relativeActionStartTime;
+ private final long relativeActionStartTimeNanos;
+ private final long relativeActionFinishTimeNanos;
private final Action failedRewoundAction;
/**
@@ -32,14 +33,23 @@
* @param relativeActionStartTime a nanotime taken before action execution began
* @param failedRewoundAction the failed action.
*/
- public ActionRewoundEvent(long relativeActionStartTime, Action failedRewoundAction) {
- this.relativeActionStartTime = relativeActionStartTime;
+ public ActionRewoundEvent(
+ long relativeActionStartTimeNanos,
+ long relativeActionFinishTimeNanos,
+ Action failedRewoundAction) {
+ this.relativeActionStartTimeNanos = relativeActionStartTimeNanos;
+ this.relativeActionFinishTimeNanos = relativeActionFinishTimeNanos;
this.failedRewoundAction = failedRewoundAction;
}
/** Returns a nanotime taken before action execution began. */
- public long getRelativeActionStartTime() {
- return relativeActionStartTime;
+ public long getRelativeActionStartTimeNanos() {
+ return relativeActionStartTimeNanos;
+ }
+
+ /** Returns a nanotime taken after action execution finished. */
+ public long getRelativeActionFinishTimeNanos() {
+ return relativeActionFinishTimeNanos;
}
/** Returns the associated action. */
