Add experimental flag to include spawn metrics in the execution log.
The SpawnMetrics proto is intended to match the existing Java class of the
same name. Note that the SpawnExec.walltime field becomes redundant, but it
is kept to ensure backwards compatibility.
This change makes it easier to correlate the metrics for corresponding actions
in two different builds.
Closes #15413.
PiperOrigin-RevId: 447938445
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java b/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java
index dc7d1f5..f0ed66c 100644
--- a/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java
+++ b/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java
@@ -119,6 +119,7 @@
new SpawnLogContext(
env.getExecRoot(),
outStream,
+ env.getOptions().getOptions(ExecutionOptions.class),
env.getOptions().getOptions(RemoteOptions.class),
env.getXattrProvider());
}
diff --git a/src/main/java/com/google/devtools/build/lib/exec/BUILD b/src/main/java/com/google/devtools/build/lib/exec/BUILD
index 642fc72..0e83326 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/exec/BUILD
@@ -248,6 +248,7 @@
name = "spawn_log_context",
srcs = ["SpawnLogContext.java"],
deps = [
+ ":execution_options",
"//src/main/java/com/google/devtools/build/lib/actions",
"//src/main/java/com/google/devtools/build/lib/actions:artifacts",
"//src/main/java/com/google/devtools/build/lib/actions:file_metadata",
@@ -260,6 +261,7 @@
"//third_party:flogger",
"//third_party:guava",
"//third_party:jsr305",
+ "//third_party/protobuf:protobuf_java",
"//third_party/protobuf:protobuf_java_util",
"@remoteapis//:build_bazel_remote_execution_v2_remote_execution_java_proto",
],
diff --git a/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java b/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java
index b9c0b7c..1bc9a6a 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java
+++ b/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java
@@ -444,6 +444,14 @@
public PathFragment executionLogBinaryFile;
@Option(
+ name = "experimental_execution_log_spawn_metrics",
+ defaultValue = "false",
+ documentationCategory = OptionDocumentationCategory.UNCATEGORIZED,
+ effectTags = {OptionEffectTag.UNKNOWN},
+ help = "Include spawn metrics in the executed spawns log.")
+ public boolean executionLogSpawnMetrics;
+
+ @Option(
name = "execution_log_json_file",
defaultValue = "null",
category = "verbosity",
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 bd954c4..df2e8cd 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
@@ -23,6 +23,7 @@
import com.google.devtools.build.lib.actions.FileArtifactValue;
import com.google.devtools.build.lib.actions.MetadataProvider;
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.Spawns;
import com.google.devtools.build.lib.actions.cache.VirtualActionInput;
@@ -58,20 +59,24 @@
* A logging utility for spawns.
*/
public class SpawnLogContext implements ActionContext {
+
private static final GoogleLogger logger = GoogleLogger.forEnclosingClass();
private final Path execRoot;
private final MessageOutputStream executionLog;
+ @Nullable private final ExecutionOptions executionOptions;
@Nullable private final RemoteOptions remoteOptions;
private final XattrProvider xattrProvider;
public SpawnLogContext(
Path execRoot,
MessageOutputStream executionLog,
+ @Nullable ExecutionOptions executionOptions,
@Nullable RemoteOptions remoteOptions,
XattrProvider xattrProvider) {
this.execRoot = execRoot;
this.executionLog = executionLog;
+ this.executionOptions = executionOptions;
this.remoteOptions = remoteOptions;
this.xattrProvider = xattrProvider;
}
@@ -162,15 +167,65 @@
builder.setProgressMessage(progressMessage);
}
builder.setMnemonic(spawn.getMnemonic());
- builder.setWalltime(Durations.fromNanos(result.getMetrics().executionWallTime().toNanos()));
+ builder.setWalltime(durationToProto(result.getMetrics().executionWallTime()));
if (spawn.getTargetLabel() != null) {
builder.setTargetLabel(spawn.getTargetLabel());
}
+ if (executionOptions != null && executionOptions.executionLogSpawnMetrics) {
+ SpawnMetrics metrics = result.getMetrics();
+ Protos.SpawnMetrics.Builder metricsBuilder = builder.getMetricsBuilder();
+ if (!metrics.totalTime().isZero()) {
+ metricsBuilder.setTotalTime(durationToProto(metrics.totalTime()));
+ }
+ if (!metrics.parseTime().isZero()) {
+ metricsBuilder.setParseTime(durationToProto(metrics.parseTime()));
+ }
+ if (!metrics.networkTime().isZero()) {
+ metricsBuilder.setNetworkTime(durationToProto(metrics.networkTime()));
+ }
+ if (!metrics.fetchTime().isZero()) {
+ metricsBuilder.setFetchTime(durationToProto(metrics.fetchTime()));
+ }
+ if (!metrics.queueTime().isZero()) {
+ metricsBuilder.setQueueTime(durationToProto(metrics.queueTime()));
+ }
+ if (!metrics.setupTime().isZero()) {
+ metricsBuilder.setSetupTime(durationToProto(metrics.setupTime()));
+ }
+ if (!metrics.uploadTime().isZero()) {
+ metricsBuilder.setUploadTime(durationToProto(metrics.uploadTime()));
+ }
+ if (!metrics.executionWallTime().isZero()) {
+ metricsBuilder.setExecutionWallTime(durationToProto(metrics.executionWallTime()));
+ }
+ if (!metrics.processOutputsTime().isZero()) {
+ metricsBuilder.setProcessOutputsTime(durationToProto(metrics.processOutputsTime()));
+ }
+ if (!metrics.retryTime().isZero()) {
+ metricsBuilder.setRetryTime(durationToProto(metrics.retryTime()));
+ }
+ metricsBuilder.setInputBytes(metrics.inputBytes());
+ metricsBuilder.setInputFiles(metrics.inputFiles());
+ metricsBuilder.setMemoryEstimateBytes(metrics.memoryEstimate());
+ metricsBuilder.setInputBytesLimit(metrics.inputBytesLimit());
+ metricsBuilder.setInputFilesLimit(metrics.inputFilesLimit());
+ metricsBuilder.setOutputBytesLimit(metrics.outputBytesLimit());
+ metricsBuilder.setOutputFilesLimit(metrics.outputFilesLimit());
+ metricsBuilder.setMemoryBytesLimit(metrics.memoryLimit());
+ if (!metrics.timeLimit().isZero()) {
+ metricsBuilder.setTimeLimit(durationToProto(metrics.timeLimit()));
+ }
+ }
+
executionLog.write(builder.build());
}
+ private static com.google.protobuf.Duration durationToProto(Duration d) {
+ return Durations.fromNanos(d.toNanos());
+ }
+
public void close() throws IOException {
executionLog.close();
}
diff --git a/src/main/protobuf/spawn.proto b/src/main/protobuf/spawn.proto
index 0f55812..f11de34 100644
--- a/src/main/protobuf/spawn.proto
+++ b/src/main/protobuf/spawn.proto
@@ -59,6 +59,48 @@
repeated Property properties = 1;
}
+// Timing, size, and memory statistics for a SpawnExec.
+message SpawnMetrics {
+ // Total wall time spent running a spawn, measured locally.
+ google.protobuf.Duration total_time = 1;
+ // Time taken to convert the spawn into a network request.
+ google.protobuf.Duration parse_time = 2;
+ // Time spent communicating over the network.
+ google.protobuf.Duration network_time = 3;
+ // Time spent fetching remote outputs.
+ google.protobuf.Duration fetch_time = 4;
+ // Time spent waiting in queues.
+ google.protobuf.Duration queue_time = 5;
+ // Time spent setting up the environment in which the spawn is run.
+ google.protobuf.Duration setup_time = 6;
+ // Time spent uploading outputs to a remote store.
+ google.protobuf.Duration upload_time = 7;
+ // Time spent running the subprocess.
+ google.protobuf.Duration execution_wall_time = 8;
+ // Time spent by the execution framework processing outputs.
+ google.protobuf.Duration process_outputs_time = 9;
+ // Time spent in previous failed attempts, not including queue time.
+ google.protobuf.Duration retry_time = 10;
+ // Total size in bytes of inputs or 0 if unavailable.
+ int64 input_bytes = 11;
+ // Total number of input files or 0 if unavailable.
+ int64 input_files = 12;
+ // Estimated memory usage or 0 if unavailable.
+ int64 memory_estimate_bytes = 13;
+ // Limit of total size of inputs or 0 if unavailable.
+ int64 input_bytes_limit = 14;
+ // Limit of total number of input files or 0 if unavailable.
+ int64 input_files_limit = 15;
+ // Limit of total size of outputs or 0 if unavailable.
+ int64 output_bytes_limit = 16;
+ // Limit of total number of output files or 0 if unavailable.
+ int64 output_files_limit = 17;
+ // Memory limit or 0 if unavailable.
+ int64 memory_bytes_limit = 18;
+ // Time limit or 0 if unavailable.
+ google.protobuf.Duration time_limit = 19;
+}
+
// Details of an executed spawn.
// These will only be generated on demand, using the
// --execution_log_file=<path> flag.
@@ -139,4 +181,7 @@
// A unique identifier for this Spawn.
Digest digest = 19;
+
+ // Timing, size and memory statistics.
+ SpawnMetrics metrics = 20;
}
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 40554dc..a1d3152 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
@@ -16,6 +16,7 @@
import static com.google.common.truth.Truth.assertThat;
import static org.junit.Assert.assertThrows;
import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.argThat;
import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.Mockito.doAnswer;
import static org.mockito.Mockito.mock;
@@ -333,7 +334,7 @@
@Test
public void testLogSpawn() throws Exception {
- setUpExecutionContext(/* remoteOptions= */ null);
+ setUpExecutionContext(/* executionOptions= */ null, /* remoteOptions= */ null);
Artifact input = ActionsTestUtil.createArtifact(rootDir, scratch.file("/execroot/foo", "1"));
scratch.file("/execroot/out1", "123");
@@ -410,7 +411,7 @@
@Test
public void testLogSpawn_noPlatform_noLoggedPlatform() throws Exception {
- setUpExecutionContext(/* remoteOptions= */ null);
+ setUpExecutionContext(/* executionOptions= */ null, /* remoteOptions= */ null);
Spawn spawn = new SpawnBuilder("cmd").build();
@@ -437,7 +438,7 @@
" value: \"1\"",
"}");
- setUpExecutionContext(remoteOptions);
+ setUpExecutionContext(/* executionOptions= */ null, remoteOptions);
Spawn spawn = new SpawnBuilder("cmd").build();
assertThrows(
SpawnExecException.class,
@@ -453,6 +454,22 @@
}
@Test
+ public void testLogSpawn_spawnMetrics() throws Exception {
+ ExecutionOptions executionOptions = Options.getDefaults(ExecutionOptions.class);
+ executionOptions.executionLogSpawnMetrics = true;
+
+ setUpExecutionContext(executionOptions, /* remoteOptions= */ null);
+
+ assertThrows(
+ SpawnExecException.class,
+ () ->
+ new TestedSpawnStrategy(execRoot, spawnRunner)
+ .exec(SIMPLE_SPAWN, actionExecutionContext));
+
+ verify(messageOutput).write(argThat((m) -> ((SpawnExec) m).hasMetrics()));
+ }
+
+ @Test
public void testLogSpawn_specifiedPlatform_overridesDefault() throws Exception {
RemoteOptions remoteOptions = Options.getDefaults(RemoteOptions.class);
remoteOptions.remoteDefaultPlatformProperties =
@@ -466,7 +483,7 @@
" name: \"a\"",
" value: \"1\"",
"}");
- setUpExecutionContext(remoteOptions);
+ setUpExecutionContext(/* executionOptions= */ null, remoteOptions);
PlatformInfo platformInfo =
PlatformInfo.builder()
@@ -500,12 +517,14 @@
verify(messageOutput).write(expected); // output will reflect default properties
}
- private void setUpExecutionContext(RemoteOptions remoteOptions) throws Exception {
+ private void setUpExecutionContext(ExecutionOptions executionOptions, RemoteOptions remoteOptions)
+ throws Exception {
when(actionExecutionContext.getContext(eq(SpawnCache.class))).thenReturn(SpawnCache.NO_CACHE);
when(actionExecutionContext.getExecRoot()).thenReturn(execRoot);
when(actionExecutionContext.getContext(eq(SpawnLogContext.class)))
.thenReturn(
- new SpawnLogContext(execRoot, messageOutput, remoteOptions, SyscallCache.NO_CACHE));
+ new SpawnLogContext(
+ execRoot, messageOutput, executionOptions, remoteOptions, SyscallCache.NO_CACHE));
when(spawnRunner.execAsync(any(Spawn.class), any(SpawnExecutionContext.class)))
.thenReturn(
FutureSpawn.immediate(
