Implemented a new event called DiscoveredInputsEvent that gets posted if the action has discoveredInputs in the ActionExecutionFunction. The discovered inputs event was added to tell the CriticalPathComputer that it took n amount of time to go through the discover input phase and to categorize it at parse time.
With the introduction of this new event, the CriticalPathComponent is now created earlier in the CriticalPathComputer#outputArtifactToComponent map so it opens up the chances of the race condition mentioned in b/19612679. To avoid the chances of hitting the race condition (regarding shared actions) the following was implemented:
Default the CriticalPathComponent#isRunning flag to false and only flip it to true when ActionStartedEvent occurs. The three scenarios where it would be flipped to true are
1. A new CriticalPathComponent is created and should start running.
2. A CriticalPathComponent has been created through discover inputs and is starting
to execute.
3. An action was rewound and starts again.
RELNOTES: None.
PiperOrigin-RevId: 282021149
diff --git a/src/main/java/com/google/devtools/build/lib/actions/DiscoveredInputsEvent.java b/src/main/java/com/google/devtools/build/lib/actions/DiscoveredInputsEvent.java
new file mode 100644
index 0000000..fd1a36b
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/actions/DiscoveredInputsEvent.java
@@ -0,0 +1,42 @@
+// Copyright 2019 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.devtools.build.lib.actions;
+
+import com.google.devtools.build.lib.events.ExtendedEventHandler;
+
+/** Event for passing SpawnMetrics for the discover inputs phase. */
+public class DiscoveredInputsEvent implements ExtendedEventHandler.ProgressLike {
+ private final SpawnMetrics metrics;
+ private final Action action;
+ private final long startTimeNanos;
+
+ public DiscoveredInputsEvent(SpawnMetrics metrics, Action action, long startTimeNanos) {
+ this.metrics = metrics;
+ this.action = action;
+ this.startTimeNanos = startTimeNanos;
+ }
+
+ public SpawnMetrics getMetrics() {
+ return metrics;
+ }
+
+ public Action getAction() {
+ return action;
+ }
+
+ public long getStartTimeNanos() {
+ return startTimeNanos;
+ }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java
index c6362324..1a60b07 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java
@@ -57,7 +57,7 @@
// These two fields are values of BlazeClock.nanoTime() at the relevant points in time.
private long startNanos;
private long finishNanos = 0;
- private volatile boolean isRunning = true;
+ private volatile boolean isRunning = false;
/** We keep here the critical path time for the most expensive child. */
private long childAggregatedElapsedTime = 0;
@@ -138,6 +138,20 @@
return action;
}
+ /**
+ * This is called by {@link CriticalPathComputer#actionStarted} to start running the action. The
+ * three scenarios where this would occur is:
+ *
+ * <ol>
+ * <li>A new CriticalPathComponent is created and should start running.
+ * <li>A CriticalPathComponent has been created with discover inputs and beginning to execute.
+ * <li>An action was rewound and starts again.
+ * </ol>
+ */
+ void startRunning() {
+ isRunning = true;
+ }
+
public boolean isRunning() {
return isRunning;
}
@@ -165,26 +179,26 @@
}
/**
- * An action can run multiple spawns. Those calls can be sequential or parallel. If it is a
- * sequence of calls we should aggregate the metrics by collecting all the SpawnResults, if they
- * are run in parallel we should keep the maximum runtime spawn. We will also set the
- * longestPhaseSpawnRunnerName to the longest running spawn runner name across all phases.
+ * An action can run multiple spawns. Those calls can be sequential or parallel. If action is a
+ * sequence of calls we aggregate the SpawnMetrics of all the SpawnResults. If there are multiples
+ * of the same action run in parallel, we keep the maximum runtime SpawnMetrics. We will also set
+ * the longestPhaseSpawnRunnerName to the longest running spawn runner name across all phases if
+ * it exists.
*/
- void addSpawnResult(SpawnResult spawnResult) {
+ void addSpawnResult(SpawnMetrics metrics, @Nullable String runnerName) {
if (this.phaseChange) {
this.totalSpawnMetrics =
SpawnMetrics.aggregateMetrics(
ImmutableList.of(this.totalSpawnMetrics, this.phaseMaxMetrics), true);
- this.phaseMaxMetrics = spawnResult.getMetrics();
+ this.phaseMaxMetrics = metrics;
this.phaseChange = false;
- } else if (spawnResult.getMetrics().totalTime().compareTo(this.phaseMaxMetrics.totalTime())
- > 0) {
- this.phaseMaxMetrics = spawnResult.getMetrics();
+ } else if (metrics.totalTime().compareTo(this.phaseMaxMetrics.totalTime()) > 0) {
+ this.phaseMaxMetrics = metrics;
}
- if (spawnResult.getMetrics().totalTime().compareTo(this.longestRunningTotalDuration) > 0) {
- this.longestPhaseSpawnRunnerName = spawnResult.getRunnerName();
- this.longestRunningTotalDuration = spawnResult.getMetrics().totalTime();
+ if (runnerName != null && metrics.totalTime().compareTo(this.longestRunningTotalDuration) > 0) {
+ this.longestPhaseSpawnRunnerName = runnerName;
+ this.longestRunningTotalDuration = metrics.totalTime();
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java
index 632acd5..0dc987c 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java
@@ -30,6 +30,7 @@
import com.google.devtools.build.lib.actions.Actions;
import com.google.devtools.build.lib.actions.Artifact;
import com.google.devtools.build.lib.actions.CachedActionEvent;
+import com.google.devtools.build.lib.actions.DiscoveredInputsEvent;
import com.google.devtools.build.lib.actions.SpawnExecutedEvent;
import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
@@ -132,6 +133,7 @@
return outputArtifactToComponent;
}
+ /** Changes the phase of the action */
@Subscribe
@AllowConcurrentEvents
public void nextCriticalPathPhase(SpawnExecutedEvent.ChangePhase phase) {
@@ -158,7 +160,7 @@
Preconditions.checkNotNull(outputArtifactToComponent.get(primaryOutput));
SpawnResult spawnResult = event.getSpawnResult();
- stats.addSpawnResult(spawnResult);
+ stats.addSpawnResult(spawnResult.getMetrics(), spawnResult.getRunnerName());
}
/** Returns the list of components using the most memory. */
@@ -194,8 +196,19 @@
.map((e) -> e.getValue());
}
+ /** Creates a CriticalPathComponent and adds the duration of input discovery and changes phase. */
+ @Subscribe
+ @AllowConcurrentEvents
+ public void discoverInputs(DiscoveredInputsEvent event) {
+ CriticalPathComponent stats =
+ tryAddComponent(createComponent(event.getAction(), event.getStartTimeNanos()));
+ stats.addSpawnResult(event.getMetrics(), null);
+ stats.changePhase();
+ }
+
/**
- * Record an action that has started to run.
+ * Record an action that has started to run. If the CriticalPathComponent has not been created,
+ * initialize it and then start running.
*
* @param event information about the started action
*/
@@ -203,7 +216,7 @@
@AllowConcurrentEvents
public void actionStarted(ActionStartedEvent event) {
Action action = event.getAction();
- tryAddComponent(createComponent(action, event.getNanoTimeStart()));
+ tryAddComponent(createComponent(action, event.getNanoTimeStart())).startRunning();
}
/**
@@ -277,8 +290,8 @@
@AllowConcurrentEvents
public void actionCached(CachedActionEvent event) {
Action action = event.getAction();
- CriticalPathComponent component
- = tryAddComponent(createComponent(action, event.getNanoTimeStart()));
+ CriticalPathComponent component =
+ tryAddComponent(createComponent(action, event.getNanoTimeStart()));
finalizeActionStat(event.getNanoTimeStart(), action, component);
}
@@ -339,24 +352,25 @@
}
}
- protected void checkCriticalPathInconsistency(
- Artifact.DerivedArtifact input, Action action, CriticalPathComponent actionStats) {
+ private void checkCriticalPathInconsistency(
+ Artifact.DerivedArtifact input, Action dependencyAction, CriticalPathComponent actionStats) {
if (!checkCriticalPathInconsistencies) {
return;
}
// Rare case that an action depending on a previously-cached shared action sees a different
// shared action that is in the midst of being an action cache hit.
- for (Artifact actionOutput : action.getOutputs()) {
+ for (Artifact actionOutput : dependencyAction.getOutputs()) {
if (input.equals(actionOutput)
&& input
.getGeneratingActionKey()
.equals(((Artifact.DerivedArtifact) actionOutput).getGeneratingActionKey())) {
- // As far as we can tell, this (currently running) action is the same action that
- // produced input, not another shared action. This should be impossible.
+ // This (currently running) dependency action is the same action that produced the input for
+ // the finished actionStats CriticalPathComponent. This should be impossible.
throw new IllegalStateException(
String.format(
- "Cannot add critical path stats when the action is not finished. %s. %s. %s",
- input, actionStats.prettyPrintAction(), action));
+ "Cannot add critical path stats when the dependency action is not finished. "
+ + "%s. %s. %s.",
+ input, actionStats.prettyPrintAction(), dependencyAction));
}
}
}
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 852a4d3..c685193 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
@@ -38,6 +38,7 @@
import com.google.devtools.build.lib.actions.AlreadyReportedActionExecutionException;
import com.google.devtools.build.lib.actions.Artifact;
import com.google.devtools.build.lib.actions.ArtifactPathResolver;
+import com.google.devtools.build.lib.actions.DiscoveredInputsEvent;
import com.google.devtools.build.lib.actions.FileArtifactValue;
import com.google.devtools.build.lib.actions.FilesetOutputSymlink;
import com.google.devtools.build.lib.actions.LostInputsActionExecutionException;
@@ -45,6 +46,7 @@
import com.google.devtools.build.lib.actions.MissingInputFileException;
import com.google.devtools.build.lib.actions.NotifyOnActionCacheHit;
import com.google.devtools.build.lib.actions.PackageRootResolver;
+import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actionsketch.ActionSketch;
import com.google.devtools.build.lib.analysis.BlazeDirectories;
import com.google.devtools.build.lib.causes.Cause;
@@ -78,6 +80,7 @@
import com.google.devtools.build.skyframe.ValueOrException;
import com.google.devtools.build.skyframe.ValueOrException2;
import java.io.IOException;
+import java.time.Duration;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
@@ -820,6 +823,10 @@
e,
action,
/*catastrophe=*/ false);
+ } finally {
+ state.discoveredInputsDuration =
+ state.discoveredInputsDuration.plus(
+ Duration.ofNanos(BlazeClock.nanoTime() - actionStartTime));
}
Preconditions.checkState(
env.valuesMissing() == (state.discoveredInputs == null),
@@ -855,6 +862,16 @@
// Set the MetadataHandler to accept output information.
metadataHandler.discardOutputMetadata();
}
+ // When discover inputs completes, post an event with the duration values.
+ env.getListener()
+ .post(
+ new DiscoveredInputsEvent(
+ new SpawnMetrics.Builder()
+ .setParseTime(state.discoveredInputsDuration)
+ .setTotalTime(state.discoveredInputsDuration)
+ .build(),
+ action,
+ actionStartTime));
}
try {
@@ -1332,6 +1349,7 @@
Token token = null;
Iterable<Artifact> discoveredInputs = null;
FileSystem actionFileSystem = null;
+ Duration discoveredInputsDuration = Duration.ZERO;
/**
* Stores the ArtifactNestedSetKeys created from the inputs of this actions. Objective: avoid
