diff options
Diffstat (limited to 'src/main')
4 files changed, 93 insertions, 52 deletions
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 a2cb5776c8..45d1057ba3 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 @@ -18,16 +18,22 @@ package com.google.devtools.build.lib.actions; */ public final class ActionCompletionEvent { - private final ActionMetadata actionMetadata; + private final long relativeActionStartTime; + private final Action action; - public ActionCompletionEvent(ActionMetadata actionMetadata) { - this.actionMetadata = actionMetadata; + public ActionCompletionEvent(long relativeActionStartTime, Action action) { + this.relativeActionStartTime = relativeActionStartTime; + this.action = action; } /** - * Returns the action metadata. + * Returns the action. */ - public ActionMetadata getActionMetadata() { - return actionMetadata; + public Action getAction() { + return action; + } + + public long getRelativeActionStartTime() { + return relativeActionStartTime; } } diff --git a/src/main/java/com/google/devtools/build/lib/runtime/AbstractCriticalPathComponent.java b/src/main/java/com/google/devtools/build/lib/runtime/AbstractCriticalPathComponent.java index b9fa84b12f..5548d8efb6 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/AbstractCriticalPathComponent.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/AbstractCriticalPathComponent.java @@ -29,7 +29,7 @@ import javax.annotation.Nullable; public class AbstractCriticalPathComponent<C extends AbstractCriticalPathComponent<C>> { /** Start time in nanoseconds. Only to be used for measuring elapsed time. */ - private final long relativeStartNanos; + private long relativeStartNanos; /** Finish time for the action in nanoseconds. Only to be used for measuring elapsed time. */ private long relativeFinishNanos = 0; protected volatile boolean isRunning = true; @@ -52,12 +52,24 @@ public class AbstractCriticalPathComponent<C extends AbstractCriticalPathCompone } /** - * Sets the finish time for the action in nanoseconds for computing the duration of the action. + * Record the elapsed time in case the new duration is greater. This method could be called + * multiple times if we run shared action concurrently and the one that really gets executed takes + * more time to send the finish event and the one that was a cache hit manages to send the event + * before. In this case we overwrite the time with the greater time. + * + * <p>This logic is known to be incorrect, as other actions that depend on this action will not + * necessarily use the correct getElapsedTimeNanos(). But we do not want to block action execution + * because of this. So in certain conditions we might see another path as the critical path. */ - public void setRelativeStartNanos(long relativeFinishNanos) { - Preconditions.checkState(isRunning, "Already stopped! %s.", action); - this.relativeFinishNanos = relativeFinishNanos; - isRunning = false; + public synchronized boolean finishActionExecution(long relativeStartNanos, + long relativeFinishNanos) { + if (isRunning || relativeFinishNanos - relativeStartNanos > getElapsedTimeNanos()) { + this.relativeStartNanos = relativeStartNanos; + this.relativeFinishNanos = relativeFinishNanos; + isRunning = false; + return true; + } + return false; } /** The action for which we are storing the stat. */ @@ -68,7 +80,7 @@ public class AbstractCriticalPathComponent<C extends AbstractCriticalPathCompone /** * Add statistics for one dependency of this action. */ - public void addDepInfo(C dep) { + public synchronized void addDepInfo(C dep) { Preconditions.checkState(!dep.isRunning, "Cannot add critical path stats when the action is not finished. %s. %s", action, dep.getAction()); 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 55e1d314a4..766a4b98b6 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 @@ -20,7 +20,6 @@ import com.google.common.collect.Maps; import com.google.common.eventbus.Subscribe; import com.google.devtools.build.lib.actions.Action; import com.google.devtools.build.lib.actions.ActionCompletionEvent; -import com.google.devtools.build.lib.actions.ActionMetadata; import com.google.devtools.build.lib.actions.ActionMiddlemanEvent; import com.google.devtools.build.lib.actions.ActionStartedEvent; import com.google.devtools.build.lib.actions.Actions; @@ -100,12 +99,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone @Subscribe public void actionStarted(ActionStartedEvent event) { Action action = event.getAction(); - C component = createComponent(action, event.getNanoTimeStart()); - for (Artifact output : action.getOutputs()) { - C old = outputArtifactToComponent.put(output, component); - Preconditions.checkState(old == null, "Duplicate output artifact found. This could happen" - + " if a previous event registered the action %s. Artifact: %s", action, output); - } + tryAddComponent(createComponent(action, event.getNanoTimeStart())); } /** @@ -118,24 +112,46 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone @Subscribe public void middlemanAction(ActionMiddlemanEvent event) { Action action = event.getAction(); - C component = createComponent(action, event.getNanoTimeStart()); - boolean duplicate = false; - for (Artifact output : action.getOutputs()) { - C old = outputArtifactToComponent.putIfAbsent(output, component); - if (old != null) { - if (!Actions.canBeShared(action, old.getAction())) { - throw new IllegalStateException("Duplicate output artifact found for middleman." - + "This could happen if a previous event registered the action.\n" - + "Old action: " + old.getAction() + "\n\n" - + "New action: " + action + "\n\n" - + "Artifact: " + output + "\n"); - } - duplicate = true; + C component = tryAddComponent(createComponent(action, event.getNanoTimeStart())); + finalizeActionStat(event.getNanoTimeStart(), action, component); + } + + /** + * Try to add the component to the map of critical path components. If there is an existing + * component for its primary output it uses that to update the rest of the outputs. + * + * @return The component to be used for updating the time stats. + */ + private C tryAddComponent(C newComponent) { + Action newAction = newComponent.getAction(); + Artifact primaryOutput = newAction.getPrimaryOutput(); + C storedComponent = outputArtifactToComponent.putIfAbsent(primaryOutput, newComponent); + + if (storedComponent != null) { + if (!Actions.canBeShared(newAction, storedComponent.getAction())) { + throw new IllegalStateException("Duplicate output artifact found for unsharable actions." + + "This could happen if a previous event registered the action.\n" + + "Old action: " + storedComponent.getAction() + "\n\n" + + "New action: " + newAction + "\n\n" + + "Artifact: " + primaryOutput + "\n"); } + } else { + storedComponent = newComponent; } - if (!duplicate) { - finalizeActionStat(action, component); + // Try to insert the existing component for the rest of the outputs even if we failed to be + // the ones inserting the component so that at the end of this method we guarantee that all the + // outputs have a component. + for (Artifact output : newAction.getOutputs()) { + if (output == primaryOutput) { + continue; + } + C old = outputArtifactToComponent.putIfAbsent(output, storedComponent); + // If two actions run concurrently maybe we find a component by primary output but we are + // the first updating the rest of the outputs. + Preconditions.checkState(old == null || old == storedComponent, + "Inconsistent state for %s", newAction); } + return storedComponent; } /** @@ -146,11 +162,8 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone @Subscribe public void actionCached(CachedActionEvent event) { Action action = event.getAction(); - C component = createComponent(action, event.getNanoTimeStart()); - for (Artifact output : action.getOutputs()) { - outputArtifactToComponent.put(output, component); - } - finalizeActionStat(action, component); + C component = tryAddComponent(createComponent(action, event.getNanoTimeStart())); + finalizeActionStat(event.getNanoTimeStart(), action, component); } /** @@ -159,10 +172,10 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone */ @Subscribe public void actionComplete(ActionCompletionEvent event) { - ActionMetadata action = event.getActionMetadata(); + Action action = event.getAction(); C component = Preconditions.checkNotNull( outputArtifactToComponent.get(action.getPrimaryOutput())); - finalizeActionStat(action, component); + finalizeActionStat(event.getRelativeActionStartTime(), action, component); } /** Maximum critical path component found during the build. */ @@ -184,8 +197,9 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone return ImmutableList.copyOf(list).reverse(); } - private void finalizeActionStat(ActionMetadata action, C component) { - component.setRelativeStartNanos(clock.nanoTime()); + private void finalizeActionStat(long startTimeNanos, Action action, C component) { + boolean updated = component.finishActionExecution(startTimeNanos, clock.nanoTime()); + for (Artifact input : action.getInputs()) { addArtifactDependency(component, input); } @@ -195,15 +209,24 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone maxCriticalPath = component; } - if (slowestComponents.size() == SLOWEST_COMPONENTS_SIZE) { - // The new component is faster than any of the slow components, avoid insertion. - if (slowestComponents.peek().getElapsedTimeNanos() >= component.getElapsedTimeNanos()) { - return; + // We do not want to fill slow components list with the same component. + // + // This might still insert a second copy of the component but only if the new self elapsed + // time is greater than the old time. That said, in practice this is not important, since + // this would happen when we have two concurrent shared actions and one is a cache hit + // because of the other one. In this case, the cache hit would not appear in the 30 slowest + // actions or we had a very fast build, so we do not care :). + if (updated) { + if (slowestComponents.size() == SLOWEST_COMPONENTS_SIZE) { + // The new component is faster than any of the slow components, avoid insertion. + if (slowestComponents.peek().getElapsedTimeNanos() >= component.getElapsedTimeNanos()) { + return; + } + // Remove the head element to make space (The fastest component in the queue). + slowestComponents.remove(); } - // Remove the head element to make space (The fastest component in the queue). - slowestComponents.remove(); + slowestComponents.add(component); } - slowestComponents.add(component); } } 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 7b71fba451..4a95f679e8 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 @@ -783,7 +783,7 @@ public final class SkyframeActionExecutor { resourceManager.releaseResources(action, estimate); } statusReporter.remove(action); - postEvent(new ActionCompletionEvent(action)); + postEvent(new ActionCompletionEvent(actionStartTime, action)); } } |