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 bazelbuild#15413. PiperOrigin-RevId: 447938445
uber-common · May 11, 2022 · b4b8b26 · b4b8b26
1 parent 1127316
commit b4b8b26
Show file tree

Hide file tree

Showing 6 changed files with 137 additions and 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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=<path> 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
@@ -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(