From b4b8b2614ae854651075506666f109d0fc508ad1 Mon Sep 17 00:00:00 2001 From: Tiago Quelhas Date: Wed, 11 May 2022 02:14:04 -0700 Subject: [PATCH] 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 --- .../build/lib/bazel/SpawnLogModule.java | 1 + .../com/google/devtools/build/lib/exec/BUILD | 2 + .../build/lib/exec/ExecutionOptions.java | 8 +++ .../build/lib/exec/SpawnLogContext.java | 57 ++++++++++++++++++- src/main/protobuf/spawn.proto | 45 +++++++++++++++ .../lib/exec/AbstractSpawnStrategyTest.java | 31 ++++++++-- 6 files changed, 137 insertions(+), 7 deletions(-) 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(