diff options
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) { |