Compute action start time in critical path using Clock.currentTimeMillis instead of nanoTime. As nanoTime should only be used to compute time differences. To avoid having to pass two long values representing time (And calling twice to Clock.xxx methods per action executed) we compute the wall time by passing a clock and computing the difference from the start nano time.

--
MOS_MIGRATED_REVID=87102963

6 files changed, 69 insertions, 45 deletions

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 9bf7a3f27b..b9fa84b12f 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
@@ -16,6 +16,9 @@ package com.google.devtools.build.lib.runtime;
 import com.google.common.base.Preconditions;
 import com.google.devtools.build.lib.actions.Action;
 import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadCompatible;
+import com.google.devtools.build.lib.util.Clock;
+
+import java.util.concurrent.TimeUnit;
 
 import javax.annotation.Nullable;
 
@@ -25,14 +28,14 @@ import javax.annotation.Nullable;
 @ThreadCompatible
 public class AbstractCriticalPathComponent<C extends AbstractCriticalPathComponent<C>> {
 
-  /** Wall time start time for the action. In milliseconds. */
-  private final long startTime;
-  /** Wall time finish time for the action. In milliseconds. */
-  private long finishTime = 0;
+  /** Start time in nanoseconds. Only to be used for measuring elapsed time. */
+  private final 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;
 
   /** We keep here the critical path time for the most expensive child. */
-  private long childAggregatedWallTime = 0;
+  private long childAggregatedElapsedTime = 0;
 
   /** The action for which we are storing the stat. */
   private final Action action;
@@ -43,15 +46,17 @@ public class AbstractCriticalPathComponent<C extends AbstractCriticalPathCompone
   @Nullable
   private C child;
 
-  public AbstractCriticalPathComponent(Action action, long startTime) {
+  public AbstractCriticalPathComponent(Action action, long relativeStartNanos) {
     this.action = action;
-    this.startTime = startTime;
+    this.relativeStartNanos = relativeStartNanos;
   }
 
-  /** Sets the finish time for the action in milliseconds. */
-  public void setFinishTimeMillis(long finishTime) {
+  /**
+   * Sets the finish time for the action in nanoseconds for computing the duration of the action.
+   */
+  public void setRelativeStartNanos(long relativeFinishNanos) {
     Preconditions.checkState(isRunning, "Already stopped! %s.", action);
-    this.finishTime = finishTime;
+    this.relativeFinishNanos = relativeFinishNanos;
     isRunning = false;
   }
 
@@ -67,32 +72,35 @@ public class AbstractCriticalPathComponent<C extends AbstractCriticalPathCompone
     Preconditions.checkState(!dep.isRunning,
         "Cannot add critical path stats when the action is not finished. %s. %s", action,
         dep.getAction());
-    long childAggregatedWallTime = dep.getAggregatedWallTime();
-    // Replace the child if its critical path had the maximum wall time.
-    if (child == null || childAggregatedWallTime > this.childAggregatedWallTime) {
-      this.childAggregatedWallTime = childAggregatedWallTime;
+    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;
       child = dep;
     }
   }
 
-  public long getActionWallTime() {
+  public long getElapsedTimeMillis() {
+    return TimeUnit.NANOSECONDS.toMillis(getElapsedTimeNanos());
+  }
+
+  long getElapsedTimeNanos() {
     Preconditions.checkState(!isRunning, "Still running %s", action);
-    return finishTime - startTime;
+    return relativeFinishNanos - relativeStartNanos;
   }
 
   /**
-   * Returns the current critical path for the action in milliseconds.
+   * Returns the current critical path for the action in nanoseconds.
    *
    * <p>Critical path is defined as : action_execution_time + max(child_critical_path).
    */
-  public long getAggregatedWallTime() {
-    Preconditions.checkState(!isRunning, "Still running %s", action);
-    return getActionWallTime() + childAggregatedWallTime;
+  public long getAggregatedElapsedTimeMillis() {
+    return TimeUnit.NANOSECONDS.toMillis(getAggregatedElapsedTimeNanos());
   }
 
-  /** Time when the action started to execute. Milliseconds since epoch time. */
-  public long getStartTime() {
-    return startTime;
+  long getAggregatedElapsedTimeNanos() {
+    Preconditions.checkState(!isRunning, "Still running %s", action);
+    return getElapsedTimeNanos() + childAggregatedElapsedTime;
   }
 
   /**
@@ -112,9 +120,20 @@ public class AbstractCriticalPathComponent<C extends AbstractCriticalPathCompone
   public String toString() {
     String currentTime = "still running ";
     if (!isRunning) {
-      currentTime = String.format("%.2f", getActionWallTime() / 1000.0) + "s ";
+      currentTime = String.format("%.2f", getElapsedTimeMillis() / 1000.0) + "s ";
     }
     return currentTime + action.describe();
   }
+
+  /**
+   * When {@code clock} is the same {@link Clock} that was used for computing
+   * {@link #relativeStartNanos}, it returns the wall time since epoch representing when
+   * the action was started.
+   */
+  public long getStartWallTimeMillis(Clock clock) {
+    long millis = clock.currentTimeMillis();
+    long nanoElapsed = clock.nanoTime();
+    return millis - TimeUnit.NANOSECONDS.toMillis((nanoElapsed - relativeStartNanos));
+  }
 }
 
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 8b072c775a..d0b70f17c5 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
@@ -73,8 +73,8 @@ public class BuildSummaryStatsModule extends BlazeModule {
         // way.
         for (SimpleCriticalPathComponent stat : criticalPath.components().reverse()) {
           Profiler.instance().logSimpleTaskDuration(
-              TimeUnit.MILLISECONDS.toNanos(stat.getStartTime()),
-              TimeUnit.MILLISECONDS.toNanos(stat.getActionWallTime()),
+              TimeUnit.MILLISECONDS.toNanos(stat.getStartWallTimeMillis(BlazeClock.instance())),
+              stat.getElapsedTimeNanos(),
               ProfilerTask.CRITICAL_PATH_COMPONENT, stat.getAction());
         }
         Profiler.instance().completeTask(ProfilerTask.CRITICAL_PATH);
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 2546492e66..55e1d314a4 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
@@ -33,7 +33,6 @@ import java.util.Collections;
 import java.util.Comparator;
 import java.util.PriorityQueue;
 import java.util.concurrent.ConcurrentMap;
-import java.util.concurrent.TimeUnit;
 
 import javax.annotation.concurrent.ThreadSafe;
 
@@ -65,7 +64,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
       new Comparator<C>() {
         @Override
         public int compare(C o1, C o2) {
-          return Long.compare(o1.getActionWallTime(), o2.getActionWallTime());
+          return Long.compare(o1.getElapsedTimeNanos(), o2.getElapsedTimeNanos());
         }
       }
   );
@@ -80,9 +79,10 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
   /**
    * Creates a critical path component for an action.
    * @param action the action for the critical path component
-   * @param startTimeMillis time when the action started to run
+   * @param relativeStartNanos time when the action started to run in nanos. Only mean to be used
+   * for computing time differences.
    */
-  protected abstract C createComponent(Action action, long startTimeMillis);
+  protected abstract C createComponent(Action action, long relativeStartNanos);
 
   /**
    * Return the critical path stats for the current command execution.
@@ -100,7 +100,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
   @Subscribe
   public void actionStarted(ActionStartedEvent event) {
     Action action = event.getAction();
-    C component = createComponent(action, TimeUnit.NANOSECONDS.toMillis(event.getNanoTimeStart()));
+    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"
@@ -118,7 +118,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
   @Subscribe
   public void middlemanAction(ActionMiddlemanEvent event) {
     Action action = event.getAction();
-    C component = createComponent(action, TimeUnit.NANOSECONDS.toMillis(event.getNanoTimeStart()));
+    C component = createComponent(action, event.getNanoTimeStart());
     boolean duplicate = false;
     for (Artifact output : action.getOutputs()) {
       C old = outputArtifactToComponent.putIfAbsent(output, component);
@@ -146,7 +146,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
   @Subscribe
   public void actionCached(CachedActionEvent event) {
     Action action = event.getAction();
-    C component = createComponent(action, TimeUnit.NANOSECONDS.toMillis(event.getNanoTimeStart()));
+    C component = createComponent(action, event.getNanoTimeStart());
     for (Artifact output : action.getOutputs()) {
       outputArtifactToComponent.put(output, component);
     }
@@ -185,7 +185,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
   }
 
   private void finalizeActionStat(ActionMetadata action, C component) {
-    component.setFinishTimeMillis(getTime());
+    component.setRelativeStartNanos(clock.nanoTime());
     for (Artifact input : action.getInputs()) {
       addArtifactDependency(component, input);
     }
@@ -197,7 +197,7 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
 
       if (slowestComponents.size() == SLOWEST_COMPONENTS_SIZE) {
         // The new component is faster than any of the slow components, avoid insertion.
-        if (slowestComponents.peek().getActionWallTime() >= component.getActionWallTime()) {
+        if (slowestComponents.peek().getElapsedTimeNanos() >= component.getElapsedTimeNanos()) {
           return;
         }
         // Remove the head element to make space (The fastest component in the queue).
@@ -207,14 +207,11 @@ public abstract class CriticalPathComputer<C extends AbstractCriticalPathCompone
     }
   }
 
-  private long getTime() {
-    return TimeUnit.NANOSECONDS.toMillis(clock.nanoTime());
-  }
-
   private boolean isBiggestCriticalPath(C newCriticalPath) {
     synchronized (lock) {
       return maxCriticalPath == null
-          || maxCriticalPath.getAggregatedWallTime() < newCriticalPath.getAggregatedWallTime();
+          || maxCriticalPath.getAggregatedElapsedTimeMillis()
+          < newCriticalPath.getAggregatedElapsedTimeMillis();
     }
   }
 
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComponent.java b/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComponent.java
index b8d5d45c83..a5fc709952 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComponent.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComponent.java
@@ -21,6 +21,8 @@ import com.google.devtools.build.lib.actions.Action;
 public class SimpleCriticalPathComponent
     extends AbstractCriticalPathComponent<SimpleCriticalPathComponent> {
 
-  public SimpleCriticalPathComponent(Action action, long startTime) { super(action, startTime); }
+  public SimpleCriticalPathComponent(Action action, long relativeStartNanos) {
+    super(action, relativeStartNanos);
+  }
 }
 
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComputer.java b/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComputer.java
index 65a9c95247..0e540581cf 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComputer.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/SimpleCriticalPathComputer.java
@@ -29,8 +29,8 @@ public class SimpleCriticalPathComputer
   }
 
   @Override
-  public SimpleCriticalPathComponent createComponent(Action action, long startTimeMillis) {
-    return new SimpleCriticalPathComponent(action, startTimeMillis);
+  public SimpleCriticalPathComponent createComponent(Action action, long relativeStartNanos) {
+    return new SimpleCriticalPathComponent(action, relativeStartNanos);
   }
 
   /**
@@ -51,7 +51,7 @@ public class SimpleCriticalPathComputer
       components.add(child);
       child = child.getChild();
     }
-    return new AggregatedCriticalPath<>(maxCriticalPath.getAggregatedWallTime(),
+    return new AggregatedCriticalPath<>(maxCriticalPath.getAggregatedElapsedTimeMillis(),
         components.build());
   }
 }
diff --git a/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java b/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java
index d4f6058169..de50bbdc68 100644
--- a/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java
+++ b/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java
@@ -29,9 +29,15 @@ public final class ManualClock implements Clock {
     return currentTimeMillis;
   }
 
+  /**
+   * Nano time should not be confused with wall time. Nano time is only mean to compute time
+   * differences. Because of this, we shift the time returned by 1000s, to test that the users
+   * of this class do not rely on nanoTime == currentTimeMillis.
+   */
   @Override
   public long nanoTime() {
-    return TimeUnit.MILLISECONDS.toNanos(currentTimeMillis);
+    return TimeUnit.MILLISECONDS.toNanos(currentTimeMillis)
+        + TimeUnit.SECONDS.toNanos(1000);
   }
 
   public void advanceMillis(long time) {