A build's or test's critical path run time was surpassing the executi…

…on run time, which is impossible. The root cause was that within the same critical path, multiple actions were run in parallel. Therefore the total run time is the union of all those actions instead of the aggregate (which was the original implementation).

For example, there are some cases where an action's dependency can run and complete during the time it's dependent action is in its discover inputs phase. In this scenario the total run time would be the
  "dependent's finish - start time"
rather than:
  "dependent's finish - start time" + "dependency's finish - start time".

The solution to get the current component's aggregate run time is to
1. Get the dep's aggregate run time
2. Add the current component's run time
3. If the dep run time and current component run time intersect, remove the delta
    - if depFinish > currentStart then total -= depFinish - currentStart

RELNOTES: Critical path run time should not have a longer run time than total execution run time.
PiperOrigin-RevId: 286383098

src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java

@@ -59,8 +59,8 @@ public static NanosToEpochConverter fromClock(Clock clock) {
   private long finishNanos = 0;
   private volatile boolean isRunning = false;
 
-  /** We keep here the critical path time for the most expensive child. */
-  private long childAggregatedElapsedTime = 0;
+  /** The longest aggregate runtime of this component and its critical path. */
+  private long aggregatedElapsedTime = 0;
 
   private final Action action;
   private final Artifact primaryOutput;
@@ -85,7 +85,6 @@ public CriticalPathComponent(int id, Action action, long startNanos) {
     this.action = Preconditions.checkNotNull(action);
     this.primaryOutput = action.getPrimaryOutput();
     this.startNanos = startNanos;
-    this.phaseChange = false;
   }
 
   /**
@@ -114,6 +113,10 @@ public synchronized void finishActionExecution(long startNanos, long finishNanos
     if (isRunning || finishNanos - startNanos > getElapsedTimeNanos()) {
       this.startNanos = startNanos;
       this.finishNanos = finishNanos;
+      // In case aggregatedElapsedTime was never set (such as a leaf node with no depedencies) with
+      // #addDepInfo, we want to set it here in which case the elapsed time is just the run time of
+      // this component.
+      aggregatedElapsedTime = Math.max(aggregatedElapsedTime, this.finishNanos - this.startNanos);
       isRunning = false;
     }
 
@@ -226,13 +229,19 @@ public String getLongestPhaseSpawnRunnerName() {
   }
 
   /**
-   * Add statistics for one dependency of this action. Caller should ensure {@code dep} not running.
+   * Updates the child component if the union of the new dependency component runtime and the
+   * current component runtime is greater than the union of the current child runtime and current
+   * component runtime. The caller should ensure the dependency component is not running.
    */
-  synchronized void addDepInfo(CriticalPathComponent dep) {
-    long childAggregatedWallTime = dep.getAggregatedElapsedTimeNanos();
-    // Replace the child if its critical path had the maximum elapsed time.
-    if (child == null || childAggregatedWallTime > this.childAggregatedElapsedTime) {
-      this.childAggregatedElapsedTime = childAggregatedWallTime;
+  synchronized void addDepInfo(CriticalPathComponent dep, long componentFinishNanos) {
+    long currentElapsedTime = componentFinishNanos - startNanos;
+    long aggregatedElapsedTime = dep.getAggregatedElapsedTimeNanos() + currentElapsedTime;
+    // This corrects the overlapping run time.
+    if (dep.finishNanos > startNanos) {
+      aggregatedElapsedTime -= dep.finishNanos - startNanos;
+    }
+    if (child == null || aggregatedElapsedTime > this.aggregatedElapsedTime) {
+      this.aggregatedElapsedTime = aggregatedElapsedTime;
       child = dep;
     }
   }
@@ -284,7 +293,7 @@ Duration getAggregatedElapsedTime() {
 
   private long getAggregatedElapsedTimeNanos() {
     Preconditions.checkState(!isRunning, "Still running %s", this);
-    return getElapsedTimeNanos() + childAggregatedElapsedTime;
+    return aggregatedElapsedTime;
   }
 
   /**

src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java

@@ -329,26 +329,25 @@ protected CriticalPathComponent getMaxCriticalPath() {
 
   private void finalizeActionStat(
       long startTimeNanos, Action action, CriticalPathComponent component) {
+    long finishTimeNanos = clock.nanoTime();
     for (Artifact input : action.getInputs()) {
-      addArtifactDependency(component, input);
+      addArtifactDependency(component, input, finishTimeNanos);
     }
-
-    component.finishActionExecution(startTimeNanos, clock.nanoTime());
+    component.finishActionExecution(startTimeNanos, finishTimeNanos);
     maxCriticalPath.accumulateAndGet(component, SELECT_LONGER_COMPONENT);
   }
 
-  /**
-   * If "input" is a generated artifact, link its critical path to the one we're building.
-   */
-  private void addArtifactDependency(CriticalPathComponent actionStats, Artifact input) {
+  /** If "input" is a generated artifact, link its critical path to the one we're building. */
+  private void addArtifactDependency(
+      CriticalPathComponent actionStats, Artifact input, long componentFinishNanos) {
     CriticalPathComponent depComponent = outputArtifactToComponent.get(input);
     if (depComponent != null) {
       if (depComponent.isRunning()) {
         checkCriticalPathInconsistency(
             (Artifact.DerivedArtifact) input, depComponent.getAction(), actionStats);
         return;
       }
-      actionStats.addDepInfo(depComponent);
+      actionStats.addDepInfo(depComponent, componentFinishNanos);
     }
   }