From 8e6af060c070ee32890ec12e0d8a19c10fca612d Mon Sep 17 00:00:00 2001 From: Cristian Hancila Date: Thu, 2 Apr 2020 12:59:38 -0700 Subject: [PATCH] Add duration tracking to spawn events (#10) --- .../build/lib/exec/SpawnLogContext.java | 5 +++ .../build/lib/remote/RemoteSpawnCache.java | 11 +++++- .../build/lib/remote/RemoteSpawnRunner.java | 4 +- .../devtools/build/lib/remote/util/Utils.java | 38 ++++++++++--------- src/main/protobuf/spawn.proto | 2 + 5 files changed, 41 insertions(+), 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 index e5116f09406805..ab4ef75b591781 100644 --- 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 index e72c04efb041d8..e8e239d4e285f1 100644 --- 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 index e4664ff142771b..89c708d45f0d5a 100644 --- 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 index d6f2ffcc1dd6ff..87b32d6d0dd93f 100644 --- 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 index f602fe625ed515..b17328b2ae9aac 100644 --- 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; }