Populate SpawnMetrics and improve CP output
Prevent non-remote executions from remote stat output in
CriticalPathComponent.
Populate metrics recorded in remote execution.
Emit SpawnExecutedEvent to supply metrics to CriticalPathComputer
subscriber after 'Actual execution' in AbstractSpawnStrategy.
Closes #10361.
PiperOrigin-RevId: 304132580
diff --git a/src/main/java/com/google/devtools/build/lib/actions/SpawnResult.java b/src/main/java/com/google/devtools/build/lib/actions/SpawnResult.java
index 2d9be26..9ddb878 100644
--- a/src/main/java/com/google/devtools/build/lib/actions/SpawnResult.java
+++ b/src/main/java/com/google/devtools/build/lib/actions/SpawnResult.java
@@ -242,6 +242,9 @@
/** Returns a file path to the action metadata log. */
Optional<MetadataLog> getActionMetadataLog();
+ /** Whether the spawn result was obtained through remote strategy. */
+ boolean wasRemote();
+
/** Basic implementation of {@link SpawnResult}. */
@Immutable
@ThreadSafe
@@ -265,6 +268,7 @@
// Invariant: Either both have a value or both are null.
@Nullable private final ActionInput inMemoryOutputFile;
@Nullable private final ByteString inMemoryContents;
+ private final boolean remote;
SimpleSpawnResult(Builder builder) {
this.exitCode = builder.exitCode;
@@ -286,6 +290,7 @@
this.inMemoryOutputFile = builder.inMemoryOutputFile;
this.inMemoryContents = builder.inMemoryContents;
this.actionMetadataLog = builder.actionMetadataLog;
+ this.remote = builder.remote;
}
@Override
@@ -414,6 +419,11 @@
public Optional<MetadataLog> getActionMetadataLog() {
return actionMetadataLog;
}
+
+ @Override
+ public boolean wasRemote() {
+ return remote;
+ }
}
/** Builder class for {@link SpawnResult}. */
@@ -437,6 +447,7 @@
// Invariant: Either both have a value or both are null.
@Nullable private ActionInput inMemoryOutputFile;
@Nullable private ByteString inMemoryContents;
+ private boolean remote;
public SpawnResult build() {
Preconditions.checkArgument(!runnerName.isEmpty());
@@ -536,6 +547,11 @@
this.actionMetadataLog = Optional.of(actionMetadataLog);
return this;
}
+
+ public Builder setRemote(boolean remote) {
+ this.remote = remote;
+ return this;
+ }
}
/** A {@link Spawn}'s metadata name and {@link Path}. */
diff --git a/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java b/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java
index f9e8eeb..5eede88 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java
+++ b/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java
@@ -32,6 +32,7 @@
import com.google.devtools.build.lib.actions.SandboxedSpawnStrategy;
import com.google.devtools.build.lib.actions.SchedulingActionEvent;
import com.google.devtools.build.lib.actions.Spawn;
+import com.google.devtools.build.lib.actions.SpawnExecutedEvent;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.Spawns;
@@ -49,6 +50,7 @@
import com.google.devtools.build.lib.vfs.PathFragment;
import java.io.IOException;
import java.time.Duration;
+import java.time.Instant;
import java.util.SortedMap;
import java.util.concurrent.atomic.AtomicInteger;
import javax.annotation.Nullable;
@@ -122,6 +124,9 @@
} else {
// Actual execution.
spawnResult = spawnRunner.execAsync(spawn, context).get();
+ actionExecutionContext
+ .getEventHandler()
+ .post(new SpawnExecutedEvent(spawn, spawnResult, Instant.now()));
if (cacheHandle.willStore()) {
cacheHandle.store(spawnResult);
}
diff --git a/src/main/java/com/google/devtools/build/lib/remote/BUILD b/src/main/java/com/google/devtools/build/lib/remote/BUILD
index eed3e55..56ccaca 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/remote/BUILD
@@ -75,6 +75,7 @@
"//third_party:netty",
"//third_party/grpc:grpc-jar",
"//third_party/protobuf:protobuf_java",
+ "//third_party/protobuf:protobuf_java_util",
"@googleapis//:google_bytestream_bytestream_java_grpc",
"@googleapis//:google_bytestream_bytestream_java_proto",
"@googleapis//:google_longrunning_operations_java_proto",
diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java
index b834667..d8aaf0b 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java
+++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java
@@ -52,6 +52,7 @@
import com.google.devtools.build.lib.remote.options.RemoteOptions;
import com.google.devtools.build.lib.remote.options.RemoteOutputsMode;
import com.google.devtools.build.lib.remote.util.DigestUtil;
+import com.google.devtools.build.lib.remote.util.NetworkTime;
import com.google.devtools.build.lib.remote.util.TracingMetadataUtils;
import com.google.devtools.build.lib.remote.util.Utils;
import com.google.devtools.build.lib.runtime.BlazeModule;
@@ -238,6 +239,7 @@
if (loggingInterceptor != null) {
interceptors.add(loggingInterceptor);
}
+ interceptors.add(new NetworkTime.Interceptor());
execChannel =
RemoteCacheClientFactory.createGrpcChannel(
remoteOptions.remoteExecutor,
@@ -258,6 +260,7 @@
if (loggingInterceptor != null) {
interceptors.add(loggingInterceptor);
}
+ interceptors.add(new NetworkTime.Interceptor());
cacheChannel =
RemoteCacheClientFactory.createGrpcChannel(
remoteOptions.remoteCache,
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 54271d2..88023c1 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
@@ -25,11 +25,13 @@
import build.bazel.remote.execution.v2.Digest;
import build.bazel.remote.execution.v2.Platform;
import com.google.common.base.Preconditions;
+import com.google.common.base.Stopwatch;
import com.google.common.collect.ImmutableSet;
import com.google.devtools.build.lib.actions.ActionInput;
import com.google.devtools.build.lib.actions.ExecException;
import com.google.devtools.build.lib.actions.FileArtifactValue;
import com.google.devtools.build.lib.actions.Spawn;
+import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.Spawns;
@@ -50,6 +52,7 @@
import com.google.devtools.build.lib.remote.options.RemoteOptions;
import com.google.devtools.build.lib.remote.options.RemoteOutputsMode;
import com.google.devtools.build.lib.remote.util.DigestUtil;
+import com.google.devtools.build.lib.remote.util.NetworkTime;
import com.google.devtools.build.lib.remote.util.TracingMetadataUtils;
import com.google.devtools.build.lib.remote.util.Utils;
import com.google.devtools.build.lib.remote.util.Utils.InMemoryOutput;
@@ -116,9 +119,16 @@
return SpawnCache.NO_RESULT_NO_STORE;
}
+ NetworkTime networkTime = new NetworkTime();
+ Stopwatch totalTime = Stopwatch.createStarted();
+
SortedMap<PathFragment, ActionInput> inputMap = context.getInputMapping(true);
MerkleTree merkleTree =
MerkleTree.build(inputMap, context.getMetadataProvider(), execRoot, digestUtil);
+ SpawnMetrics.Builder spawnMetrics =
+ new SpawnMetrics.Builder()
+ .setInputBytes(merkleTree.getInputBytes())
+ .setInputFiles(merkleTree.getInputFiles());
Digest merkleTreeRoot = merkleTree.getRootDigest();
// Get the remote platform properties.
@@ -138,7 +148,8 @@
// Look up action cache, and reuse the action output if it is found.
ActionKey actionKey = digestUtil.computeActionKey(action);
Context withMetadata =
- TracingMetadataUtils.contextWithMetadata(buildRequestId, commandId, actionKey);
+ TracingMetadataUtils.contextWithMetadata(buildRequestId, commandId, actionKey)
+ .withValue(NetworkTime.CONTEXT_KEY, networkTime);
Profiler prof = Profiler.instance();
if (options.remoteAcceptCached
@@ -161,6 +172,7 @@
remoteOutputsMode,
/* exitCode = */ 0,
hasFilesToDownload(spawn.getOutputFiles(), filesToDownload));
+ Stopwatch fetchTime = Stopwatch.createStarted();
if (downloadOutputs) {
try (SilentCloseable c =
prof.profile(ProfilerTask.REMOTE_DOWNLOAD, "download outputs")) {
@@ -183,9 +195,19 @@
context::lockOutputFiles);
}
}
+ fetchTime.stop();
+ totalTime.stop();
+ spawnMetrics
+ .setFetchTime(fetchTime.elapsed())
+ .setTotalTime(totalTime.elapsed())
+ .setNetworkTime(networkTime.getDuration());
SpawnResult spawnResult =
createSpawnResult(
- result.getExitCode(), /* cacheHit= */ true, "remote", inMemoryOutput);
+ result.getExitCode(),
+ /* cacheHit= */ true,
+ "remote",
+ inMemoryOutput,
+ spawnMetrics.build());
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 118ce6c..b9abd58 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
@@ -30,10 +30,12 @@
import build.bazel.remote.execution.v2.Digest;
import build.bazel.remote.execution.v2.ExecuteRequest;
import build.bazel.remote.execution.v2.ExecuteResponse;
+import build.bazel.remote.execution.v2.ExecutedActionMetadata;
import build.bazel.remote.execution.v2.LogFile;
import build.bazel.remote.execution.v2.Platform;
import com.google.common.annotations.VisibleForTesting;
import com.google.common.base.Preconditions;
+import com.google.common.base.Stopwatch;
import com.google.common.base.Strings;
import com.google.common.base.Throwables;
import com.google.common.collect.ImmutableList;
@@ -46,6 +48,7 @@
import com.google.devtools.build.lib.actions.CommandLines.ParamFileActionInput;
import com.google.devtools.build.lib.actions.ExecException;
import com.google.devtools.build.lib.actions.Spawn;
+import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.Spawns;
@@ -67,6 +70,7 @@
import com.google.devtools.build.lib.remote.options.RemoteOptions;
import com.google.devtools.build.lib.remote.options.RemoteOutputsMode;
import com.google.devtools.build.lib.remote.util.DigestUtil;
+import com.google.devtools.build.lib.remote.util.NetworkTime;
import com.google.devtools.build.lib.remote.util.TracingMetadataUtils;
import com.google.devtools.build.lib.remote.util.Utils;
import com.google.devtools.build.lib.remote.util.Utils.InMemoryOutput;
@@ -77,6 +81,9 @@
import com.google.protobuf.Any;
import com.google.protobuf.InvalidProtocolBufferException;
import com.google.protobuf.Message;
+import com.google.protobuf.Timestamp;
+import com.google.protobuf.util.Durations;
+import com.google.protobuf.util.Timestamps;
import com.google.rpc.PreconditionFailure;
import com.google.rpc.PreconditionFailure.Violation;
import io.grpc.Context;
@@ -94,6 +101,7 @@
import java.util.SortedMap;
import java.util.TreeSet;
import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.function.Supplier;
import javax.annotation.Nullable;
/** A client for the remote execution service. */
@@ -192,7 +200,7 @@
@Override
public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
throws ExecException, InterruptedException, IOException {
-
+ Stopwatch totalTime = Stopwatch.createStarted();
boolean spawnCacheableRemotely = Spawns.mayBeCachedRemotely(spawn);
boolean uploadLocalResults = remoteOptions.remoteUploadLocalResults && spawnCacheableRemotely;
boolean acceptCachedResult = remoteOptions.remoteAcceptCached && spawnCacheableRemotely;
@@ -202,6 +210,10 @@
SortedMap<PathFragment, ActionInput> inputMap = context.getInputMapping(true);
final MerkleTree merkleTree =
MerkleTree.build(inputMap, context.getMetadataProvider(), execRoot, digestUtil);
+ SpawnMetrics.Builder spawnMetrics =
+ new SpawnMetrics.Builder()
+ .setInputBytes(merkleTree.getInputBytes())
+ .setInputFiles(merkleTree.getInputFiles());
maybeWriteParamFilesLocally(spawn);
// Get the remote platform properties.
@@ -218,13 +230,17 @@
Action action =
buildAction(
commandHash, merkleTree.getRootDigest(), context.getTimeout(), spawnCacheableRemotely);
- ActionKey actionKey = digestUtil.computeActionKey(action);
+
+ spawnMetrics.setParseTime(totalTime.elapsed());
Preconditions.checkArgument(
Spawns.mayBeExecutedRemotely(spawn), "Spawn can't be executed remotely. This is a bug.");
+ NetworkTime networkTime = new NetworkTime();
// Look up action cache, and reuse the action output if it is found.
+ ActionKey actionKey = digestUtil.computeActionKey(action);
Context withMetadata =
- TracingMetadataUtils.contextWithMetadata(buildRequestId, commandId, actionKey);
+ TracingMetadataUtils.contextWithMetadata(buildRequestId, commandId, actionKey)
+ .withValue(NetworkTime.CONTEXT_KEY, networkTime);
Context previous = withMetadata.attach();
Profiler prof = Profiler.instance();
try {
@@ -246,7 +262,14 @@
} else {
try {
return downloadAndFinalizeSpawnResult(
- cachedResult, /* cacheHit= */ true, spawn, context, remoteOutputsMode);
+ cachedResult,
+ /* cacheHit= */ true,
+ spawn,
+ context,
+ remoteOutputsMode,
+ totalTime,
+ networkTime::getDuration,
+ spawnMetrics);
} catch (CacheNotFoundException e) {
// No cache hit, so we fall through to local or remote execution.
// We set acceptCachedResult to false in order to force the action re-execution.
@@ -284,7 +307,14 @@
Map<Digest, Message> additionalInputs = Maps.newHashMapWithExpectedSize(2);
additionalInputs.put(actionKey.getDigest(), action);
additionalInputs.put(commandHash, command);
+ Duration networkTimeStart = networkTime.getDuration();
+ Stopwatch uploadTime = Stopwatch.createStarted();
remoteCache.ensureInputsPresent(merkleTree, additionalInputs);
+ // subtract network time consumed here to ensure wall clock during upload is not
+ // double
+ // counted, and metrics time computation does not exceed total time
+ spawnMetrics.setUploadTime(
+ uploadTime.elapsed().minus(networkTime.getDuration().minus(networkTimeStart)));
}
ExecuteResponse reply;
try (SilentCloseable c = prof.profile(REMOTE_EXECUTION, "execute remotely")) {
@@ -300,13 +330,22 @@
outErr.printErr(message + "\n");
}
+ spawnMetricsAccounting(spawnMetrics, actionResult.getExecutionMetadata());
+
try (SilentCloseable c = prof.profile(REMOTE_DOWNLOAD, "download server logs")) {
maybeDownloadServerLogs(reply, actionKey);
}
try {
return downloadAndFinalizeSpawnResult(
- actionResult, reply.getCachedResult(), spawn, context, remoteOutputsMode);
+ actionResult,
+ reply.getCachedResult(),
+ spawn,
+ context,
+ remoteOutputsMode,
+ totalTime,
+ networkTime::getDuration,
+ spawnMetrics);
} catch (CacheNotFoundException e) {
// No cache hit, so if we retry this execution, we must no longer accept
// cached results, it must be reexecuted
@@ -323,12 +362,60 @@
}
}
+ /** conversion utility for protobuf Timestamp difference to java.time.Duration */
+ private static Duration between(Timestamp from, Timestamp to) {
+ return Duration.ofNanos(Durations.toNanos(Timestamps.between(from, to)));
+ }
+
+ @VisibleForTesting
+ static void spawnMetricsAccounting(
+ SpawnMetrics.Builder spawnMetrics, ExecutedActionMetadata executionMetadata) {
+ // Expect that a non-empty worker indicates that all fields are populated.
+ // If the bounded sides of these checkpoints are default timestamps, i.e. unset,
+ // the phase durations can be extremely large. Unset pairs, or a fully unset
+ // collection of timestamps, will result in zeroed durations, and no metrics
+ // contributions for a phase or phases.
+ if (!executionMetadata.getWorker().isEmpty()) {
+ // Accumulate queueTime from any previous attempts
+ Duration remoteQueueTime =
+ spawnMetrics
+ .build()
+ .remoteQueueTime()
+ .plus(
+ between(
+ executionMetadata.getQueuedTimestamp(),
+ executionMetadata.getWorkerStartTimestamp()));
+ spawnMetrics.setRemoteQueueTime(remoteQueueTime);
+ // setup time does not include failed attempts
+ Duration setupTime =
+ between(
+ executionMetadata.getWorkerStartTimestamp(),
+ executionMetadata.getExecutionStartTimestamp());
+ spawnMetrics.setSetupTime(setupTime);
+ // execution time is unspecified for failures
+ Duration executionWallTime =
+ between(
+ executionMetadata.getExecutionStartTimestamp(),
+ executionMetadata.getExecutionCompletedTimestamp());
+ spawnMetrics.setExecutionWallTime(executionWallTime);
+ // remoteProcessOutputs time is unspecified for failures
+ Duration remoteProcessOutputsTime =
+ between(
+ executionMetadata.getOutputUploadStartTimestamp(),
+ executionMetadata.getOutputUploadCompletedTimestamp());
+ spawnMetrics.setRemoteProcessOutputsTime(remoteProcessOutputsTime);
+ }
+ }
+
private SpawnResult downloadAndFinalizeSpawnResult(
ActionResult actionResult,
boolean cacheHit,
Spawn spawn,
SpawnExecutionContext context,
- RemoteOutputsMode remoteOutputsMode)
+ RemoteOutputsMode remoteOutputsMode,
+ Stopwatch totalTime,
+ Supplier<Duration> networkTime,
+ SpawnMetrics.Builder spawnMetrics)
throws ExecException, IOException, InterruptedException {
boolean downloadOutputs =
shouldDownloadAllSpawnOutputs(
@@ -336,6 +423,8 @@
/* exitCode = */ actionResult.getExitCode(),
hasFilesToDownload(spawn.getOutputFiles(), filesToDownload));
InMemoryOutput inMemoryOutput = null;
+ Duration networkTimeStart = networkTime.get();
+ Stopwatch fetchTime = Stopwatch.createStarted();
if (downloadOutputs) {
try (SilentCloseable c = Profiler.instance().profile(REMOTE_DOWNLOAD, "download outputs")) {
remoteCache.download(
@@ -356,7 +445,21 @@
context::lockOutputFiles);
}
}
- return createSpawnResult(actionResult.getExitCode(), cacheHit, getName(), inMemoryOutput);
+ fetchTime.stop();
+ totalTime.stop();
+ Duration networkTimeEnd = networkTime.get();
+ // subtract network time consumed here to ensure wall clock during fetch is not double
+ // counted, and metrics time computation does not exceed total time
+ return createSpawnResult(
+ actionResult.getExitCode(),
+ cacheHit,
+ getName(),
+ inMemoryOutput,
+ spawnMetrics
+ .setFetchTime(fetchTime.elapsed().minus(networkTimeEnd.minus(networkTimeStart)))
+ .setTotalTime(totalTime.elapsed())
+ .setNetworkTime(networkTimeEnd)
+ .build());
}
@Override
diff --git a/src/main/java/com/google/devtools/build/lib/remote/merkletree/MerkleTree.java b/src/main/java/com/google/devtools/build/lib/remote/merkletree/MerkleTree.java
index 7115601..7fac053 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/merkletree/MerkleTree.java
+++ b/src/main/java/com/google/devtools/build/lib/remote/merkletree/MerkleTree.java
@@ -33,6 +33,7 @@
import java.util.HashMap;
import java.util.Map;
import java.util.SortedMap;
+import java.util.concurrent.atomic.AtomicLong;
import javax.annotation.Nullable;
/** A merkle tree representation as defined by the remote execution api. */
@@ -68,14 +69,20 @@
private final Map<Digest, Directory> digestDirectoryMap;
private final Map<Digest, PathOrBytes> digestFileMap;
private final Digest rootDigest;
+ private final long inputFiles;
+ private final long inputBytes;
private MerkleTree(
Map<Digest, Directory> digestDirectoryMap,
Map<Digest, PathOrBytes> digestFileMap,
- Digest rootDigest) {
+ Digest rootDigest,
+ long inputFiles,
+ long inputBytes) {
this.digestDirectoryMap = digestDirectoryMap;
this.digestFileMap = digestFileMap;
this.rootDigest = rootDigest;
+ this.inputFiles = inputFiles;
+ this.inputBytes = inputBytes;
}
/** Returns the digest of the merkle tree's root. */
@@ -83,6 +90,16 @@
return rootDigest;
}
+ /** Returns the number of files represented by this merkle tree */
+ public long getInputFiles() {
+ return inputFiles;
+ }
+
+ /** Returns the sum of file sizes plus protobuf sizes used to represent this merkle tree */
+ public long getInputBytes() {
+ return inputBytes;
+ }
+
@Nullable
public Directory getDirectoryByDigest(Digest digest) {
return digestDirectoryMap.get(digest);
@@ -143,31 +160,38 @@
private static MerkleTree build(DirectoryTree tree, DigestUtil digestUtil) {
Preconditions.checkNotNull(tree);
if (tree.isEmpty()) {
- return new MerkleTree(ImmutableMap.of(), ImmutableMap.of(), digestUtil.compute(new byte[0]));
+ return new MerkleTree(
+ ImmutableMap.of(), ImmutableMap.of(), digestUtil.compute(new byte[0]), 0, 0);
}
Map<Digest, Directory> digestDirectoryMap =
Maps.newHashMapWithExpectedSize(tree.numDirectories());
Map<Digest, PathOrBytes> digestPathMap = Maps.newHashMapWithExpectedSize(tree.numFiles());
Map<PathFragment, Digest> m = new HashMap<>();
+ AtomicLong inputBytes = new AtomicLong(0);
tree.visit(
(dirname, files, dirs) -> {
Directory.Builder b = Directory.newBuilder();
for (DirectoryTree.FileNode file : files) {
b.addFiles(buildProto(file));
digestPathMap.put(file.getDigest(), toPathOrBytes(file));
+ inputBytes.addAndGet(file.getDigest().getSizeBytes());
}
for (DirectoryTree.DirectoryNode dir : dirs) {
PathFragment subDirname = dirname.getRelative(dir.getPathSegment());
Digest protoDirDigest =
Preconditions.checkNotNull(m.remove(subDirname), "protoDirDigest was null");
b.addDirectories(buildProto(dir, protoDirDigest));
+ inputBytes.addAndGet(protoDirDigest.getSizeBytes());
}
Directory protoDir = b.build();
Digest protoDirDigest = digestUtil.compute(protoDir);
digestDirectoryMap.put(protoDirDigest, protoDir);
m.put(dirname, protoDirDigest);
});
- return new MerkleTree(digestDirectoryMap, digestPathMap, m.get(PathFragment.EMPTY_FRAGMENT));
+ Digest rootDigest = m.get(PathFragment.EMPTY_FRAGMENT);
+ inputBytes.addAndGet(rootDigest.getSizeBytes());
+ return new MerkleTree(
+ digestDirectoryMap, digestPathMap, rootDigest, tree.numFiles(), inputBytes.get());
}
private static FileNode buildProto(DirectoryTree.FileNode file) {
diff --git a/src/main/java/com/google/devtools/build/lib/remote/util/BUILD b/src/main/java/com/google/devtools/build/lib/remote/util/BUILD
index ceb78d0..2ab7faa 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/util/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/remote/util/BUILD
@@ -16,6 +16,7 @@
deps = [
"//src/main/java/com/google/devtools/build/lib:build-base",
"//src/main/java/com/google/devtools/build/lib/actions",
+ "//src/main/java/com/google/devtools/build/lib/concurrent",
"//src/main/java/com/google/devtools/build/lib/remote/common",
"//src/main/java/com/google/devtools/build/lib/remote/options",
"//src/main/java/com/google/devtools/build/lib/vfs",
@@ -24,6 +25,7 @@
"//third_party:jsr305",
"//third_party/grpc:grpc-jar",
"//third_party/protobuf:protobuf_java",
+ "@remoteapis//:build_bazel_remote_execution_v2_remote_execution_java_grpc",
"@remoteapis//:build_bazel_remote_execution_v2_remote_execution_java_proto",
],
)
diff --git a/src/main/java/com/google/devtools/build/lib/remote/util/NetworkTime.java b/src/main/java/com/google/devtools/build/lib/remote/util/NetworkTime.java
new file mode 100644
index 0000000..1f51559
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/remote/util/NetworkTime.java
@@ -0,0 +1,108 @@
+// Copyright 2019 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package com.google.devtools.build.lib.remote.util;
+
+import build.bazel.remote.execution.v2.ExecutionGrpc;
+import com.google.common.base.Stopwatch;
+import com.google.devtools.build.lib.concurrent.ThreadSafety;
+import io.grpc.CallOptions;
+import io.grpc.Channel;
+import io.grpc.ClientCall;
+import io.grpc.ClientInterceptor;
+import io.grpc.Context;
+import io.grpc.ForwardingClientCall;
+import io.grpc.ForwardingClientCallListener;
+import io.grpc.Metadata;
+import io.grpc.MethodDescriptor;
+import io.grpc.Status;
+import java.time.Duration;
+
+/** Reentrant wall clock stopwatch and grpc interceptor for network waits. */
+@ThreadSafety.ThreadSafe
+public class NetworkTime {
+ public static final Context.Key<NetworkTime> CONTEXT_KEY = Context.key("remote-network-time");
+
+ private final Stopwatch wallTime = Stopwatch.createUnstarted();
+ private int outstanding = 0;
+
+ private synchronized void start() {
+ if (!wallTime.isRunning()) {
+ wallTime.start();
+ }
+ outstanding++;
+ }
+
+ private synchronized void stop() {
+ if (--outstanding == 0) {
+ wallTime.stop();
+ }
+ }
+
+ public Duration getDuration() {
+ return wallTime.elapsed();
+ }
+
+ /** The ClientInterceptor used to track network time. */
+ public static class Interceptor implements ClientInterceptor {
+ @Override
+ public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(
+ MethodDescriptor<ReqT, RespT> method, CallOptions callOptions, Channel next) {
+ ClientCall<ReqT, RespT> call = next.newCall(method, callOptions);
+ // prevent accounting for execution wait time
+ if (method != ExecutionGrpc.getExecuteMethod()
+ && method != ExecutionGrpc.getWaitExecutionMethod()) {
+ NetworkTime networkTime = CONTEXT_KEY.get();
+ if (networkTime != null) {
+ call = new NetworkTimeCall<>(call, networkTime);
+ }
+ }
+ return call;
+ }
+ }
+
+ private static class NetworkTimeCall<ReqT, RespT>
+ extends ForwardingClientCall.SimpleForwardingClientCall<ReqT, RespT> {
+ private final NetworkTime networkTime;
+ private boolean firstMessage = true;
+
+ protected NetworkTimeCall(ClientCall<ReqT, RespT> delegate, NetworkTime networkTime) {
+ super(delegate);
+ this.networkTime = networkTime;
+ }
+
+ @Override
+ public void start(Listener<RespT> responseListener, Metadata headers) {
+ super.start(
+ new ForwardingClientCallListener.SimpleForwardingClientCallListener<RespT>(
+ responseListener) {
+
+ @Override
+ public void onClose(Status status, Metadata trailers) {
+ networkTime.stop();
+ super.onClose(status, trailers);
+ }
+ },
+ headers);
+ }
+
+ @Override
+ public void sendMessage(ReqT message) {
+ if (firstMessage) {
+ networkTime.start();
+ firstMessage = false;
+ }
+ super.sendMessage(message);
+ }
+ }
+}
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 79f7c68..abf3170 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
@@ -23,6 +23,7 @@
import com.google.devtools.build.lib.actions.ActionInput;
import com.google.devtools.build.lib.actions.ExecutionRequirements;
import com.google.devtools.build.lib.actions.Spawn;
+import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.remote.common.CacheNotFoundException;
@@ -83,13 +84,19 @@
/** Constructs a {@link SpawnResult}. */
public static SpawnResult createSpawnResult(
- int exitCode, boolean cacheHit, String runnerName, @Nullable InMemoryOutput inMemoryOutput) {
+ int exitCode,
+ boolean cacheHit,
+ String runnerName,
+ @Nullable InMemoryOutput inMemoryOutput,
+ SpawnMetrics spawnMetrics) {
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);
+ .setCacheHit(cacheHit)
+ .setSpawnMetrics(spawnMetrics)
+ .setRemote(true);
if (inMemoryOutput != null) {
builder.setInMemoryOutput(inMemoryOutput.getOutput(), inMemoryOutput.getContents());
}
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java
index 2fef7c9..d18fc25 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComponent.java
@@ -80,6 +80,9 @@
/** Child with the maximum critical path. */
@Nullable private CriticalPathComponent child;
+ /** Indication that there is at least one remote spawn metrics received. */
+ private boolean remote = false;
+
public CriticalPathComponent(int id, Action action, long startNanos) {
this.id = id;
this.action = Preconditions.checkNotNull(action);
@@ -188,7 +191,13 @@
* the longestPhaseSpawnRunnerName to the longest running spawn runner name across all phases if
* it exists.
*/
- void addSpawnResult(SpawnMetrics metrics, @Nullable String runnerName) {
+ void addSpawnResult(SpawnMetrics metrics, @Nullable String runnerName, boolean wasRemote) {
+ // Mark this component as having remote components if _any_ spawn result contributing
+ // to it contains meaningful remote metrics. Subsequent non-remote spawns in an action
+ // must not reset this flag.
+ if (wasRemote) {
+ this.remote = true;
+ }
if (this.phaseChange) {
this.totalSpawnMetrics =
SpawnMetrics.aggregateMetrics(
@@ -320,8 +329,10 @@
currentTime = String.format("%.2f", getElapsedTimeNoCheck().toMillis() / 1000.0) + "s";
}
sb.append(currentTime);
- sb.append(", Remote ");
- sb.append(getSpawnMetrics().toString(getElapsedTimeNoCheck(), /* summary= */ false));
+ if (remote) {
+ sb.append(", Remote ");
+ sb.append(getSpawnMetrics().toString(getElapsedTimeNoCheck(), /* summary= */ false));
+ }
sb.append(" ");
sb.append(getActionString());
return sb.toString();
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java
index 8259aa1..7e64fad 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CriticalPathComputer.java
@@ -160,7 +160,8 @@
Preconditions.checkNotNull(outputArtifactToComponent.get(primaryOutput));
SpawnResult spawnResult = event.getSpawnResult();
- stats.addSpawnResult(spawnResult.getMetrics(), spawnResult.getRunnerName());
+ stats.addSpawnResult(
+ spawnResult.getMetrics(), spawnResult.getRunnerName(), spawnResult.wasRemote());
}
/** Returns the list of components using the most memory. */
@@ -202,7 +203,7 @@
public void discoverInputs(DiscoveredInputsEvent event) {
CriticalPathComponent stats =
tryAddComponent(createComponent(event.getAction(), event.getStartTimeNanos()));
- stats.addSpawnResult(event.getMetrics(), null);
+ stats.addSpawnResult(event.getMetrics(), null, /* wasRemote=*/ false);
stats.changePhase();
}
diff --git a/src/test/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategyTest.java b/src/test/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategyTest.java
index 8585639..c469fb8 100644
--- a/src/test/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategyTest.java
+++ b/src/test/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategyTest.java
@@ -32,6 +32,7 @@
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.util.ActionsTestUtil;
import com.google.devtools.build.lib.analysis.platform.PlatformInfo;
+import com.google.devtools.build.lib.events.StoredEventHandler;
import com.google.devtools.build.lib.exec.Protos.Digest;
import com.google.devtools.build.lib.exec.Protos.EnvironmentVariable;
import com.google.devtools.build.lib.exec.Protos.File;
@@ -85,6 +86,8 @@
MockitoAnnotations.initMocks(this);
scratch = new Scratch(fs);
rootDir = ArtifactRoot.asSourceRoot(Root.fromPath(scratch.dir("/execroot")));
+ StoredEventHandler eventHandler = new StoredEventHandler();
+ when(actionExecutionContext.getEventHandler()).thenReturn(eventHandler);
}
@Test
@@ -146,7 +149,6 @@
verify(spawnRunner, never()).execAsync(any(Spawn.class), any(SpawnExecutionContext.class));
}
- @SuppressWarnings("unchecked")
@Test
public void testCacheMiss() throws Exception {
SpawnCache cache = mock(SpawnCache.class);
@@ -172,7 +174,6 @@
verify(entry).store(eq(spawnResult));
}
- @SuppressWarnings("unchecked")
@Test
public void testCacheMissWithNonZeroExit() throws Exception {
SpawnCache cache = mock(SpawnCache.class);
diff --git a/src/test/java/com/google/devtools/build/lib/remote/BUILD b/src/test/java/com/google/devtools/build/lib/remote/BUILD
index 290fe63..f8fca23 100644
--- a/src/test/java/com/google/devtools/build/lib/remote/BUILD
+++ b/src/test/java/com/google/devtools/build/lib/remote/BUILD
@@ -82,6 +82,7 @@
"//third_party:truth",
"//third_party/grpc:grpc-jar",
"//third_party/protobuf:protobuf_java",
+ "//third_party/protobuf:protobuf_java_util",
"@googleapis//:google_bytestream_bytestream_java_grpc",
"@googleapis//:google_bytestream_bytestream_java_proto",
"@googleapis//:google_longrunning_operations_java_proto",
diff --git a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java
index 4082565..0a90dea 100644
--- a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java
+++ b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java
@@ -26,13 +26,13 @@
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
-import static org.mockito.Mockito.verifyZeroInteractions;
import static org.mockito.Mockito.when;
import build.bazel.remote.execution.v2.ActionResult;
import build.bazel.remote.execution.v2.Digest;
import build.bazel.remote.execution.v2.ExecuteRequest;
import build.bazel.remote.execution.v2.ExecuteResponse;
+import build.bazel.remote.execution.v2.ExecutedActionMetadata;
import build.bazel.remote.execution.v2.LogFile;
import com.google.common.collect.ClassToInstanceMap;
import com.google.common.collect.ImmutableClassToInstanceMap;
@@ -54,6 +54,7 @@
import com.google.devtools.build.lib.actions.ResourceSet;
import com.google.devtools.build.lib.actions.SimpleSpawn;
import com.google.devtools.build.lib.actions.Spawn;
+import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.util.ActionsTestUtil;
@@ -86,10 +87,14 @@
import com.google.devtools.build.lib.vfs.PathFragment;
import com.google.devtools.build.lib.vfs.inmemoryfs.InMemoryFileSystem;
import com.google.devtools.common.options.Options;
+import com.google.protobuf.Timestamp;
+import com.google.protobuf.util.Durations;
+import com.google.protobuf.util.Timestamps;
import com.google.rpc.Code;
import java.io.IOException;
import java.io.InputStream;
import java.nio.charset.StandardCharsets;
+import java.time.Duration;
import java.util.List;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
@@ -192,7 +197,7 @@
verify(cache, never())
.downloadActionResult(any(ActionKey.class), /* inlineOutErr= */ eq(false));
verify(cache, never()).upload(any(), any(), any(), any(), any(), any());
- verifyZeroInteractions(localRunner);
+ verifyNoMoreInteractions(localRunner);
}
private FakeSpawnExecutionContext getSpawnContext(Spawn spawn) {
@@ -965,6 +970,51 @@
.downloadMinimal(eq(succeededAction), anyCollection(), any(), any(), any(), any(), any());
}
+ @Test
+ public void accountingDisabledWithoutWorker() {
+ SpawnMetrics.Builder spawnMetrics = Mockito.mock(SpawnMetrics.Builder.class);
+ RemoteSpawnRunner.spawnMetricsAccounting(
+ spawnMetrics, ExecutedActionMetadata.getDefaultInstance());
+ verifyNoMoreInteractions(spawnMetrics);
+ }
+
+ @Test
+ public void accountingAddsDurationsForStages() {
+ SpawnMetrics.Builder builder =
+ new SpawnMetrics.Builder()
+ .setRemoteQueueTime(Duration.ofSeconds(1))
+ .setSetupTime(Duration.ofSeconds(2))
+ .setExecutionWallTime(Duration.ofSeconds(2))
+ .setRemoteProcessOutputsTime(Duration.ofSeconds(2));
+ Timestamp queued = Timestamp.getDefaultInstance();
+ com.google.protobuf.Duration oneSecond = Durations.fromMillis(1000);
+ Timestamp workerStart = Timestamps.add(queued, oneSecond);
+ Timestamp executionStart = Timestamps.add(workerStart, oneSecond);
+ Timestamp executionCompleted = Timestamps.add(executionStart, oneSecond);
+ Timestamp outputUploadStart = Timestamps.add(executionCompleted, oneSecond);
+ Timestamp outputUploadComplete = Timestamps.add(outputUploadStart, oneSecond);
+ ExecutedActionMetadata executedMetadata =
+ ExecutedActionMetadata.newBuilder()
+ .setWorker("test worker")
+ .setQueuedTimestamp(queued)
+ .setWorkerStartTimestamp(workerStart)
+ .setExecutionStartTimestamp(executionStart)
+ .setExecutionCompletedTimestamp(executionCompleted)
+ .setOutputUploadStartTimestamp(outputUploadStart)
+ .setOutputUploadCompletedTimestamp(outputUploadComplete)
+ .build();
+ RemoteSpawnRunner.spawnMetricsAccounting(builder, executedMetadata);
+ SpawnMetrics spawnMetrics = builder.build();
+ // remote queue time is accumulated
+ assertThat(spawnMetrics.remoteQueueTime()).isEqualTo(Duration.ofSeconds(2));
+ // setup time is substituted
+ assertThat(spawnMetrics.setupTime()).isEqualTo(Duration.ofSeconds(1));
+ // execution time is unspecified, assume substituted
+ assertThat(spawnMetrics.executionWallTime()).isEqualTo(Duration.ofSeconds(1));
+ // remoteProcessOutputs time is unspecified, assume substituted
+ assertThat(spawnMetrics.remoteProcessOutputsTime()).isEqualTo(Duration.ofSeconds(1));
+ }
+
private static Spawn newSimpleSpawn(Artifact... outputs) {
return simpleSpawnWithExecutionInfo(ImmutableMap.of(), outputs);
}
