Add Logging for non-increasing Clock#nanoTime calls.
We see negative duration values when calling CriticalPathComponent#getElapsedTime and these values are sometimes very large (from 7 days to 77 days). Add a logger when we get the finish time so we can compare the start and finish times at that moment.
RELNOTES: None.
PiperOrigin-RevId: 312732191
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 7e64fad..ed15f4c 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,6 +20,8 @@
import com.google.common.collect.Maps;
import com.google.common.eventbus.AllowConcurrentEvents;
import com.google.common.eventbus.Subscribe;
+import com.google.common.flogger.GoogleLogger;
+import com.google.common.flogger.StackSize;
import com.google.devtools.build.lib.actions.Action;
import com.google.devtools.build.lib.actions.ActionAnalysisMetadata;
import com.google.devtools.build.lib.actions.ActionCompletionEvent;
@@ -35,6 +37,7 @@
import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.clock.Clock;
+import java.time.Duration;
import java.util.Comparator;
import java.util.List;
import java.util.Map;
@@ -52,6 +55,8 @@
*/
@ThreadSafe
public class CriticalPathComputer {
+ private static final GoogleLogger logger = GoogleLogger.forEnclosingClass();
+
/** Number of top actions to record. */
static final int SLOWEST_COMPONENTS_SIZE = 30;
private static final int LARGEST_MEMORY_COMPONENTS_SIZE = 20;
@@ -334,6 +339,12 @@
for (Artifact input : action.getInputs().toList()) {
addArtifactDependency(component, input, finishTimeNanos);
}
+ if (Duration.ofNanos(finishTimeNanos - startTimeNanos).compareTo(Duration.ofMillis(-5)) < 0) {
+ // See note in {@link Clock#nanoTime} about non increasing subsequent #nanoTime calls.
+ logger.atWarning().withStackTrace(StackSize.MEDIUM).log(
+ "Negative duration time for [%s] %s with start: %s, finish: %s.",
+ action.getMnemonic(), action.getPrimaryOutput(), startTimeNanos, finishTimeNanos);
+ }
component.finishActionExecution(startTimeNanos, finishTimeNanos);
maxCriticalPath.accumulateAndGet(component, SELECT_LONGER_COMPONENT);
}
