Store start/end timestamps of locally executed actions in the disk ca…

src/main/java/com/google/devtools/build/lib/actions/SpawnResult.java

@@ -26,6 +26,7 @@
 import com.google.protobuf.ByteString;
 import java.io.InputStream;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.Locale;
 import java.util.Optional;
 import javax.annotation.Nullable;
@@ -169,6 +170,14 @@ default boolean isCatastrophe() {
   /** Returns optional details about the runner. */
   String getRunnerSubtype();
 
+  /**
+   * Returns the start time for the {@link Spawn}'s execution.
+   *
+   * @return the measurement, or empty in case of execution errors or when the measurement is not
+   *     implemented for the current platform
+   */
+  Optional<Instant> getStartTime();
+
   /**
    * Returns the wall time taken by the {@link Spawn}'s execution.
    *
@@ -270,6 +279,7 @@ final class SimpleSpawnResult implements SpawnResult {
     private final String runnerName;
     private final String runnerSubtype;
     private final SpawnMetrics spawnMetrics;
+    private final Optional<Instant> startTime;
     private final Optional<Duration> wallTime;
     private final Optional<Duration> userTime;
     private final Optional<Duration> systemTime;
@@ -296,6 +306,7 @@ final class SimpleSpawnResult implements SpawnResult {
       this.spawnMetrics = builder.spawnMetrics != null
           ? builder.spawnMetrics
           : SpawnMetrics.forLocalExecution(builder.wallTime.orElse(Duration.ZERO));
+      this.startTime = builder.startTime;
       this.wallTime = builder.wallTime;
       this.userTime = builder.userTime;
       this.systemTime = builder.systemTime;
@@ -347,6 +358,11 @@ public SpawnMetrics getMetrics() {
       return spawnMetrics;
     }
 
+    @Override
+    public Optional<Instant> getStartTime() {
+      return startTime;
+    }
+
     @Override
     public Optional<Duration> getWallTime() {
       return wallTime;
@@ -451,6 +467,7 @@ final class Builder {
     private String runnerName = "";
     private String runnerSubtype = "";
     private SpawnMetrics spawnMetrics;
+    private Optional<Instant> startTime = Optional.empty();
     private Optional<Duration> wallTime = Optional.empty();
     private Optional<Duration> userTime = Optional.empty();
     private Optional<Duration> systemTime = Optional.empty();
@@ -535,6 +552,11 @@ public Builder setSpawnMetrics(SpawnMetrics spawnMetrics) {
       return this;
     }
 
+    public Builder setStartTime(Instant startTime) {
+      this.startTime = Optional.of(startTime);
+      return this;
+    }
+
     public Builder setWallTime(Duration wallTime) {
       this.wallTime = Optional.of(wallTime);
       return this;

src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java

@@ -63,6 +63,7 @@
 import java.io.InterruptedIOException;
 import java.io.OutputStream;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.EnumMap;
 import java.util.List;
@@ -385,6 +386,8 @@ private SpawnResult start()
         subprocessBuilder.setArgv(args);
 
         long startTime = System.currentTimeMillis();
+        spawnResultBuilder.setStartTime(Instant.now());
+        Stopwatch executionStopwatch = Stopwatch.createStarted();
         TerminationStatus terminationStatus;
         try (SilentCloseable c =
             Profiler.instance()

src/main/java/com/google/devtools/build/lib/remote/RemoteExecutionService.java

@@ -1178,8 +1178,10 @@ private Single<UploadManifest> buildUploadManifestAsync(
               action.action,
               action.command,
               outputFiles.build(),
-              action.spawnExecutionContext.getFileOutErr(),
-              spawnResult.exitCode());
+              action.getSpawnExecutionContext().getFileOutErr(),
+              spawnResult.exitCode(),
+              spawnResult.getStartTime(),
+              spawnResult.getWallTime());
         });
   }
 

src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java

@@ -127,6 +127,8 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
                   /*cacheHit=*/ true,
                   result.cacheName(),
                   inMemoryOutput,
+                  result.getExecutionMetadata().getWorkerStartTimestamp(),
+                  result.getExecutionMetadata().getWorkerCompletedTimestamp(),
                   spawnMetrics.build(),
                   spawn.getMnemonic());
           return SpawnCache.success(spawnResult);

src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java

@@ -377,6 +377,8 @@ private SpawnResult downloadAndFinalizeSpawnResult(
         cacheHit,
         cacheName,
         inMemoryOutput,
+        result.getExecutionMetadata().getWorkerStartTimestamp(),
+        result.getExecutionMetadata().getWorkerCompletedTimestamp(),
         spawnMetrics
             .setFetchTime(fetchTime.elapsed().minus(networkTimeEnd.minus(networkTimeStart)))
             .setTotalTime(totalTime.elapsed())

src/main/java/com/google/devtools/build/lib/remote/UploadManifest.java

@@ -52,16 +52,20 @@
 import com.google.devtools.build.lib.vfs.PathFragment;
 import com.google.devtools.build.lib.vfs.Symlinks;
 import com.google.protobuf.ByteString;
+import com.google.protobuf.Timestamp;
 import io.reactivex.rxjava3.core.Completable;
 import io.reactivex.rxjava3.core.Flowable;
 import io.reactivex.rxjava3.core.Single;
 import java.io.IOException;
+import java.time.Duration;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.Comparator;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Optional;
 import java.util.stream.Collectors;
 import javax.annotation.Nullable;
 
@@ -88,7 +92,9 @@ public static UploadManifest create(
       Command command,
       Collection<Path> outputFiles,
       FileOutErr outErr,
-      int exitCode)
+      int exitCode,
+      Optional<Instant> startTime,
+      Optional<Duration> wallTime)
       throws ExecException, IOException {
     ActionResult.Builder result = ActionResult.newBuilder();
     result.setExitCode(exitCode);
@@ -110,9 +116,23 @@ public static UploadManifest create(
       result.setStdoutDigest(manifest.getStdoutDigest());
     }
 
+    if (startTime.isPresent() && wallTime.isPresent()) {
+      result
+          .getExecutionMetadataBuilder()
+          .setWorkerStartTimestamp(instantToTimestamp(startTime.get()))
+          .setWorkerCompletedTimestamp(instantToTimestamp(startTime.get().plus(wallTime.get())));
+    }
+
     return manifest;
   }
 
+  private static Timestamp instantToTimestamp(Instant instant) {
+    return Timestamp.newBuilder()
+        .setSeconds(instant.getEpochSecond())
+        .setNanos(instant.getNano())
+        .build();
+  }
+
   /**
    * Create an UploadManifest from an ActionResult builder and an exec root. The ActionResult
    * builder is populated through a call to {@link #addFile(Digest, Path)}.

src/main/java/com/google/devtools/build/lib/remote/util/Utils.java

@@ -52,6 +52,7 @@
 import com.google.protobuf.ByteString;
 import com.google.protobuf.Duration;
 import com.google.protobuf.InvalidProtocolBufferException;
+import com.google.protobuf.Timestamp;
 import com.google.protobuf.util.Durations;
 import com.google.rpc.BadRequest;
 import com.google.rpc.Code;
@@ -69,6 +70,7 @@
 import java.io.OutputStream;
 import java.text.DecimalFormat;
 import java.text.DecimalFormatSymbols;
+import java.time.Instant;
 import java.util.Arrays;
 import java.util.Collection;
 import java.util.Locale;
@@ -144,6 +146,8 @@ public static SpawnResult createSpawnResult(
       boolean cacheHit,
       String runnerName,
       @Nullable InMemoryOutput inMemoryOutput,
+      Timestamp executionStartTimestamp,
+      Timestamp executionCompletedTimestamp,
       SpawnMetrics spawnMetrics,
       String mnemonic) {
     SpawnResult.Builder builder =
@@ -153,6 +157,11 @@ public static SpawnResult createSpawnResult(
             .setExitCode(exitCode)
             .setRunnerName(cacheHit ? runnerName + " cache hit" : runnerName)
             .setCacheHit(cacheHit)
+            .setStartTime(timestampToInstant(executionStartTimestamp))
+            .setWallTime(
+                java.time.Duration.between(
+                    timestampToInstant(executionStartTimestamp),
+                    timestampToInstant(executionCompletedTimestamp)))
             .setSpawnMetrics(spawnMetrics)
             .setRemote(true);
     if (exitCode != 0) {
@@ -170,6 +179,10 @@ public static SpawnResult createSpawnResult(
     return builder.build();
   }
 
+  private static Instant timestampToInstant(Timestamp timestamp) {
+    return Instant.ofEpochSecond(timestamp.getSeconds(), timestamp.getNanos());
+  }
+
   /** Returns {@code true} if all spawn outputs should be downloaded to disk. */
   public static boolean shouldDownloadAllSpawnOutputs(
       RemoteOutputsMode remoteOutputsMode, int exitCode, boolean hasTopLevelOutputs) {

src/main/java/com/google/devtools/build/lib/sandbox/AbstractSandboxSpawnRunner.java

@@ -53,6 +53,7 @@
 import com.google.devtools.build.lib.vfs.Path;
 import java.io.IOException;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.Map;
 
 /** Abstract common ancestor for sandbox spawn runners implementing the common parts. */
@@ -181,7 +182,7 @@ private final SpawnResult run(
     if (useSubprocessTimeout) {
       subprocessBuilder.setTimeoutMillis(timeout.toMillis());
     }
-    long startTime = System.currentTimeMillis();
+    Instant startTime = Instant.now();
     TerminationStatus terminationStatus;
     try {
       Subprocess subprocess = subprocessBuilder.start();
@@ -210,7 +211,7 @@ private final SpawnResult run(
     }
 
     // TODO(b/62588075): Calculate wall time inside Subprocess instead?
-    Duration wallTime = Duration.ofMillis(System.currentTimeMillis() - startTime);
+    Duration wallTime = Duration.between(startTime, Instant.now());
     boolean wasTimeout =
         (useSubprocessTimeout && terminationStatus.timedOut())
             || (!useSubprocessTimeout && wasTimeout(timeout, wallTime));
@@ -254,6 +255,7 @@ private final SpawnResult run(
             .setRunnerName(getName())
             .setStatus(status)
             .setExitCode(exitCode)
+            .setStartTime(startTime)
             .setWallTime(wallTime)
             .setFailureMessage(failureMessage);
 

src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java

@@ -220,6 +220,7 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
             .setRunnerName(getName())
             .setExitCode(exitCode)
             .setStatus(exitCode == 0 ? Status.SUCCESS : Status.NON_ZERO_EXIT)
+            .setStartTime(startTime)
             .setWallTime(wallTime)
             .setSpawnMetrics(spawnMetrics.setTotalTime(wallTime).build());
     if (exitCode != 0) {

src/test/java/com/google/devtools/build/lib/remote/GrpcCacheClientTest.java

@@ -108,6 +108,7 @@
 import java.util.List;
 import java.util.concurrent.Executors;
 import java.util.concurrent.TimeUnit;
+import java.util.Optional;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.function.Supplier;
@@ -580,7 +581,9 @@ private ActionResult upload(
             command,
             outputs,
             outErr,
-            0);
+            /* exitCode= */ 0,
+            /* startTime= */ Optional.empty(),
+            /* wallTime= */ Optional.empty());
     return uploadManifest.upload(context, remoteCache, NullEventHandler.INSTANCE);
   }
 

src/test/shell/bazel/remote/remote_execution_test.sh

@@ -3627,4 +3627,40 @@ EOF
   expect_log "Executing genrule .* failed: (Exit 1):"
 }
 
+
+function test_local_test_execution_with_disk_cache() {
+  # Tests that the wall time for a locally executed test is correctly cached.
+  # If not, the generate-xml.sh action, which embeds the wall time, will be
+  # considered stale on a cache hit.
+  # Regression test for https://github.com/bazelbuild/bazel/issues/14426.
+
+  mkdir -p a
+  cat > a/BUILD <<EOF
+sh_test(
+  name = 'test',
+  srcs = ['test.sh'],
+)
+EOF
+  cat > a/test.sh <<EOF
+sleep 1
+EOF
+  chmod +x a/test.sh
+
+  CACHEDIR=$(mktemp -d)
+
+  bazel test \
+    --disk_cache=$CACHEDIR \
+    //a:test >& $TEST_log || "Failed to build //a:test"
+
+  expect_log "5 processes: 3 internal, 2 .*-sandbox"
+
+  bazel clean
+
+  bazel test \
+    --disk_cache=$CACHEDIR \
+    //a:test >& $TEST_log || "Failed to build //a:test"
+
+  expect_log "5 processes: 2 disk cache hit, 3 internal"
+}
+
 run_suite "Remote execution and remote cache tests"

src/tools/remote/src/main/java/com/google/devtools/build/remote/worker/ExecutionServer.java

@@ -65,11 +65,13 @@
 import java.io.IOException;
 import java.nio.file.FileAlreadyExistsException;
 import java.time.Duration;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Optional;
 import java.util.UUID;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ExecutionException;
@@ -293,7 +295,7 @@ private ActionResult execute(
     // implementation instead of copying it.
     com.google.devtools.build.lib.shell.Command cmd =
         getCommand(command, workingDirectory.getPathString());
-    long startTime = System.currentTimeMillis();
+    Instant startTime = Instant.now();
     CommandResult cmdResult = null;
 
     String uuid = UUID.randomUUID().toString();
@@ -316,13 +318,14 @@ private ActionResult execute(
         }
       }
 
+      Duration wallTime = Duration.between(startTime, Instant.now());
       long timeoutMillis =
           action.hasTimeout()
               ? Durations.toMillis(action.getTimeout())
               : TimeUnit.MINUTES.toMillis(15);
       boolean wasTimeout =
           (cmdResult != null && cmdResult.getTerminationStatus().timedOut())
-              || wasTimeout(timeoutMillis, System.currentTimeMillis() - startTime);
+              || wasTimeout(timeoutMillis, wallTime.toMillis());
       final int exitCode;
       Status errStatus = null;
       ExecuteResponse.Builder resp = ExecuteResponse.newBuilder();
@@ -356,7 +359,9 @@ private ActionResult execute(
                 command,
                 outputs,
                 outErr,
-                exitCode);
+                exitCode,
+                Optional.of(startTime),
+                Optional.of(wallTime));
         result = manifest.upload(context, cache, NullEventHandler.INSTANCE);
       } catch (ExecException e) {
         if (errStatus == null) {