Use a single critical path component in case of shared actions that run concurrently. We update the timing with the maximum elapsed time. This could prevent us from getting the critical path (because another smaller path could mask the critical path), but in practice we do not expect this to happen.

--
MOS_MIGRATED_REVID=89133458

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