Add duration tracking to spawn events (bazelbuild#10)

nkoroste · Nov 3, 2020 · 8e6af06 · 8e6af06
1 parent ff47321
commit 8e6af06
Show file tree

Hide file tree

Showing 5 changed files with 41 additions and 19 deletions.
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
@@ -134,6 +134,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
@@ -164,8 +164,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
@@ -180,14 +184,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(),
@@ -198,6 +205,7 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
  execRoot,
  context.getMetadataInjector(),
  context::lockOutputFiles);
+ downloadDuration += System.nanoTime() - now;
  }
  }
  fetchTime.stop();
@@ -213,7 +221,8 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context)
  "remote",
  inMemoryOutput,
  spawnMetrics.build(),
- spawn.getMnemonic());
+ spawn.getMnemonic(),
+ downloadDuration);
  return SpawnCache.success(spawnResult);
  }
  } catch (CacheNotFoundException e) {

diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java
@@ -105,6 +105,7 @@
 import java.util.Map;
 import java.util.SortedMap;
 import java.util.TreeSet;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.function.Supplier;
 import javax.annotation.Nullable;
@@ -517,7 +518,8 @@ private SpawnResult downloadAndFinalizeSpawnResult(
  .setTotalTime(totalTime.elapsed())
  .setNetworkTime(networkTimeEnd)
  .build(),
- spawn.getMnemonic());
+ spawn.getMnemonic(),
+ totalTime.elapsed(TimeUnit.NANOSECONDS));
  }
 
  @Override

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;
@@ -88,26 +89,29 @@ public static PathFragment getInMemoryOutputPath(Spawn spawn) {
 
  /** Constructs a {@link SpawnResult}. */
  public static SpawnResult createSpawnResult(
- int exitCode,
- boolean cacheHit,
- String runnerName,
- @Nullable InMemoryOutput inMemoryOutput,
- SpawnMetrics spawnMetrics,
- String mnemonic) {
+ int exitCode,
+ boolean cacheHit,
+ String runnerName,
+ @Nullable InMemoryOutput inMemoryOutput,
+ SpawnMetrics spawnMetrics,
+ String mnemonic,
+ 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)
- .setRemote(true);
+ 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))
+ .setRemote(true);
+
  if (exitCode != 0) {
  builder.setFailureDetail(
- FailureDetail.newBuilder()
- .setMessage(mnemonic + " returned a non-zero exit code when running remotely")
- .setSpawn(FailureDetails.Spawn.newBuilder().setCode(Code.NON_ZERO_EXIT))
- .build());
+  FailureDetail.newBuilder()
+  .setMessage(mnemonic + " returned a non-zero exit code when running remotely")
+  .setSpawn(FailureDetails.Spawn.newBuilder().setCode(Code.NON_ZERO_EXIT))
+  .build());
  }
  if (inMemoryOutput != null) {
  builder.setInMemoryOutput(inMemoryOutput.getOutput(), inMemoryOutput.getContents());

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;
 }