From 9843d25a6eb84433f744d6d21ac09d205fdfce2e Mon Sep 17 00:00:00 2001 From: Fabian Meumertzheim Date: Thu, 6 Aug 2026 08:18:02 -0700 Subject: [PATCH] Re-sample the execution graph clock converter per command (https://github.com/bazelbuild/bazel/pull/30594) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ### Description `ExecutionGraphModule` built its `NanosToMillisSinceEpochConverter` in a *field initializer*: ```java private NanosToMillisSinceEpochConverter nanosToMillis = BlazeClock.createNanosToMillisSinceEpochConverter(); ``` Modules are instantiated once per server, so that converter captures the offset between the monotonic and the wall clock as it stood at server startup, and is then reused for every command that server ever serves. Build it in `beforeCommand` instead, so each command converts through an offset sampled during that command. ### Motivation `System.nanoTime()` and `System.currentTimeMillis()` are backed by different operating system clocks, and the offset between them is not constant. NTP steps the wall clock when it corrects it. A virtual machine does so more dramatically: shortly after boot, and again whenever a snapshot is resumed — while the monotonic clock never steps and does not advance across the pause. A long-lived server that survives a snapshot resume keeps converting with an offset captured before the snapshot, so every `start_timestamp_millis` it writes into the execution graph log afterwards is shifted by the entire time the snapshot spent on disk. Anything that reconstructs a timeline from the log — critical path, action concurrency, correlation against other traces on the machine — is wrong by that amount. On bare metal an NTP step produces the same corruption at a smaller magnitude. ### Build API Changes No ### Checklist - [ ] I have added tests for the new use cases (if any). - [ ] I have updated the documentation (if applicable). ### Release Notes RELNOTES: None Closes #30594. PiperOrigin-RevId: 960312424 Change-Id: I3295137f08c41bc6d76593766e4a8386dd548fb5 (cherry picked from commit 13e656ce47ccdb665381059226f51d17e7c4312e) --- .../build/lib/runtime/ExecutionGraphModule.java | 14 ++++++++++---- .../lib/runtime/ExecutionGraphModuleTest.java | 10 +++------- 2 files changed, 13 insertions(+), 11 deletions(-) diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java b/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java index d3bf5d9a5d923c..222dcfcbc1998d 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java @@ -187,8 +187,7 @@ public DependencyInfoConverter() { private ActionDumpWriter writer; private CommandEnvironment env; private WalkableGraph graph; - private NanosToMillisSinceEpochConverter nanosToMillis = - BlazeClock.createNanosToMillisSinceEpochConverter(); + private NanosToMillisSinceEpochConverter nanosToMillis; // Only relevant for Skymeld: there may be multiple events and we only count the first one. private final AtomicBoolean executionStarted = new AtomicBoolean(); @@ -210,13 +209,20 @@ void setGraph(WalkableGraph graph) { } @VisibleForTesting - void setNanosToMillis(NanosToMillisSinceEpochConverter nanosToMillis) { - this.nanosToMillis = nanosToMillis; + void resetNanosToMillis() { + this.nanosToMillis = BlazeClock.createNanosToMillisSinceEpochConverter(); + } + + @VisibleForTesting + NanosToMillisSinceEpochConverter getNanosToMillis() { + return nanosToMillis; } @Override public void beforeCommand(CommandEnvironment env) { this.env = env; + // The offset between monotonic and wall clock time may change between commands. + resetNanosToMillis(); if (env.getCommand().buildPhase().executes()) { ExecutionGraphOptions options = diff --git a/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphModuleTest.java b/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphModuleTest.java index 4d55603a8bdff6..8a263b900e80d0 100644 --- a/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphModuleTest.java +++ b/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphModuleTest.java @@ -54,7 +54,6 @@ import com.google.devtools.build.lib.buildtool.BuildResult; import com.google.devtools.build.lib.buildtool.BuildResult.BuildToolLogCollection; import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; -import com.google.devtools.build.lib.clock.BlazeClock; import com.google.devtools.build.lib.collect.nestedset.NestedSetBuilder; import com.google.devtools.build.lib.collect.nestedset.Order; import com.google.devtools.build.lib.exec.util.FakeActionInputFileCache; @@ -96,6 +95,7 @@ public class ExecutionGraphModuleTest extends FoundationTestCase { @Before public void createModule() { module = new ExecutionGraphModule(); + module.resetNanosToMillis(); } @Before @@ -671,8 +671,6 @@ public void spawnAndAction_withSameOutputs() throws Exception { public void spawnAndAction_withDifferentOutputs() throws Exception { var buffer = new ByteArrayOutputStream(); startLogging(eventBus, UUID.randomUUID(), buffer, DependencyInfo.ALL); - var nanosToMillis = BlazeClock.createNanosToMillisSinceEpochConverter(); - module.setNanosToMillis(nanosToMillis); module.spawnExecuted( new SpawnExecutedEvent( @@ -705,7 +703,7 @@ public void spawnAndAction_withDifferentOutputs() throws Exception { .setIndex(1) .setMetrics( ExecutionGraph.Metrics.newBuilder() - .setStartTimestampMillis(nanosToMillis.toEpochMillis(0))) + .setStartTimestampMillis(module.getNanosToMillis().toEpochMillis(0))) .setRuleClass("dummy-kind") .build()); } @@ -714,8 +712,6 @@ public void spawnAndAction_withDifferentOutputs() throws Exception { public void noSpawnAction_hasCorrectDuration() throws Exception { var buffer = new ByteArrayOutputStream(); startLogging(eventBus, UUID.randomUUID(), buffer, DependencyInfo.ALL); - var nanosToMillis = BlazeClock.createNanosToMillisSinceEpochConverter(); - module.setNanosToMillis(nanosToMillis); var action = new ActionsTestUtil.NullAction(createOutputArtifact("foo/out")); module.actionComplete( @@ -727,7 +723,7 @@ public void noSpawnAction_hasCorrectDuration() throws Exception { executionGraphNodeBuilderForAction(action) .setMetrics( ExecutionGraph.Metrics.newBuilder() - .setStartTimestampMillis(nanosToMillis.toEpochMillis(1000000)) + .setStartTimestampMillis(module.getNanosToMillis().toEpochMillis(1000000)) .setDurationMillis(1) .setProcessMillis(1)) .setRuleClass("dummy-kind")