Add duration tracking to spawn events (bazelbuild#10)

nkoroste · Jul 14, 2020 · 9cb27e3 · 9cb27e3
1 parent 8e2e050
commit 9cb27e3
Show file tree

Hide file tree

Showing 4 changed files with 40 additions and 1 deletion.
diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java
@@ -133,6 +133,11 @@ public void logSpawn(
     if (!timeout.isZero()) {
       builder.setTimeoutMillis(timeout.toMillis());
     }
+
+    if (result.getWallTime().isPresent()) {
+      builder.setWallTime(result.getWallTime().get().getNano());
+    }
+
     builder.setCacheable(Spawns.mayBeCached(spawn));
     builder.setExitCode(result.exitCode());
     builder.setRemoteCacheHit(result.isCacheHit());

diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java
@@ -160,8 +160,12 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
       Context previous = withMetadata.attach();
       try {
         ActionResult result;
+        long downloadDuration = 0;
+
         try (SilentCloseable c = prof.profile(ProfilerTask.REMOTE_CACHE_CHECK, "check cache hit")) {
+          long now = System.nanoTime();
           result = remoteCache.downloadActionResult(actionKey, /* inlineOutErr= */ false);
+          downloadDuration += System.nanoTime() - now;
         }
         // In case the remote cache returned a failed action (exit code != 0) we treat it as a
         // cache miss
@@ -176,14 +180,17 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
           if (downloadOutputs) {
             try (SilentCloseable c =
                 prof.profile(ProfilerTask.REMOTE_DOWNLOAD, "download outputs")) {
+              long now = System.nanoTime();
               remoteCache.download(
                   result, execRoot, context.getFileOutErr(), context::lockOutputFiles);
+              downloadDuration += System.nanoTime() - now;
             }
           } else {
             PathFragment inMemoryOutputPath = getInMemoryOutputPath(spawn);
             // inject output metadata
             try (SilentCloseable c =
                 prof.profile(ProfilerTask.REMOTE_DOWNLOAD, "download outputs minimal")) {
+              long now = System.nanoTime();
               inMemoryOutput =
                   remoteCache.downloadMinimal(
                       actionKey.getDigest().getHash(),
@@ -194,6 +201,7 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
                       execRoot,
                       context.getMetadataInjector(),
                       context::lockOutputFiles);
+              downloadDuration += System.nanoTime() - now;
             }
           }
           fetchTime.stop();
@@ -208,7 +216,8 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
                   /* cacheHit= */ true,
                   "remote",
                   inMemoryOutput,
-                  spawnMetrics.build());
+                  spawnMetrics.build(),
+                  downloadDuration);
           return SpawnCache.success(spawnResult);
         }
       } catch (CacheNotFoundException e) {

diff --git a/src/main/java/com/google/devtools/build/lib/remote/util/Utils.java b/src/main/java/com/google/devtools/build/lib/remote/util/Utils.java
@@ -38,6 +38,7 @@
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
 import java.io.OutputStream;
+import java.time.Duration;
 import java.util.Collection;
 import java.util.Collections;
 import java.util.concurrent.ExecutionException;
@@ -114,6 +115,28 @@ public static SpawnResult createSpawnResult(
     return builder.build();
   }
 
+  /** Constructs a {@link SpawnResult}. */
+  public static SpawnResult createSpawnResult(
+          int exitCode,
+          boolean cacheHit,
+          String runnerName,
+          @Nullable InMemoryOutput inMemoryOutput,
+          SpawnMetrics spawnMetrics,
+          long duration) {
+    SpawnResult.Builder builder =
+            new SpawnResult.Builder()
+                    .setStatus(exitCode == 0 ? Status.SUCCESS : Status.NON_ZERO_EXIT)
+                    .setExitCode(exitCode)
+                    .setRunnerName(cacheHit ? runnerName + " cache hit" : runnerName)
+                    .setCacheHit(cacheHit)
+                    .setSpawnMetrics(spawnMetrics)
+                    .setWallTime(Duration.ofNanos(duration));
+    if (inMemoryOutput != null) {
+      builder.setInMemoryOutput(inMemoryOutput.getOutput(), inMemoryOutput.getContents());
+    }
+    return builder.build();
+  }
+
   /** Returns {@code true} if all spawn outputs should be downloaded to disk. */
   public static boolean shouldDownloadAllSpawnOutputs(
       RemoteOutputsMode remoteOutputsMode, int exitCode, boolean hasTopLevelOutputs) {

diff --git a/src/main/protobuf/spawn.proto b/src/main/protobuf/spawn.proto
@@ -123,4 +123,6 @@ message SpawnExec {
   // Its semantics varies greatly depending on the status field.
   // Dependable: if status is empty, exit_code is guaranteed to be zero.
   int32 exit_code = 15;
+
+  uint64 wall_time = 16;
 }