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 dc7d1f5c159abb..f0ed66c41d0566 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 @@ private void initOutputs(CommandEnvironment env) throws IOException { 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 642fc72df46aa4..0e83326fe0cdb8 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 @@ java_library( 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 @@ java_library( "//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 b9c0b7ce0ee697..1bc9a6aecae559 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 @@ -443,6 +443,14 @@ public boolean usingLocalTestJobs() { + " --subcommands (for displaying subcommands in terminal output).") 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", 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 bd954c42c683a3..df2e8cdc6aa1fb 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 @@ public void logSpawn( 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 0f55812d519478..f11de34f13d177 100644 --- a/src/main/protobuf/spawn.proto +++ b/src/main/protobuf/spawn.proto @@ -59,6 +59,48 @@ message Platform { 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= flag. @@ -139,4 +181,7 @@ message SpawnExec { // 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 40554dc760b73c..a1d315267231cc 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 @@ public void testCacheMissWithNonZeroExit() throws Exception { @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 @@ public void testLogSpawn() throws Exception { @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 @@ public void testLogSpawn_defaultPlatform_getsLogged() throws Exception { " value: \"1\"", "}"); - setUpExecutionContext(remoteOptions); + setUpExecutionContext(/* executionOptions= */ null, remoteOptions); Spawn spawn = new SpawnBuilder("cmd").build(); assertThrows( SpawnExecException.class, @@ -452,6 +453,22 @@ public void testLogSpawn_defaultPlatform_getsLogged() throws Exception { verify(messageOutput).write(expected); // output will reflect default properties } + @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); @@ -466,7 +483,7 @@ public void testLogSpawn_specifiedPlatform_overridesDefault() throws Exception { " name: \"a\"", " value: \"1\"", "}"); - setUpExecutionContext(remoteOptions); + setUpExecutionContext(/* executionOptions= */ null, remoteOptions); PlatformInfo platformInfo = PlatformInfo.builder() @@ -500,12 +517,14 @@ public void testLogSpawn_specifiedPlatform_overridesDefault() throws Exception { 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(