Include input discovery time in the execution graph.

The CriticalPathComputer includes it as parse time, but here, we can add another field.

PiperOrigin-RevId: 500757360
Change-Id: I954fcb90b575a0bfd535dc190f7958fc689ae84f

Author: Googler

src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphModule.java

@@ -31,6 +31,7 @@
 import com.google.devtools.build.lib.actions.ActionMiddlemanEvent;
 import com.google.devtools.build.lib.actions.Artifact;
 import com.google.devtools.build.lib.actions.CachedActionEvent;
+import com.google.devtools.build.lib.actions.DiscoveredInputsEvent;
 import com.google.devtools.build.lib.actions.ExecutionGraph;
 import com.google.devtools.build.lib.actions.RunfilesSupplier;
 import com.google.devtools.build.lib.actions.Spawn;
@@ -263,6 +264,17 @@ public void buildComplete(BuildCompleteEvent event) {
       }
     }
   }
+
+  /** Records the input discovery time. */
+  @Subscribe
+  @AllowConcurrentEvents
+  public void discoverInputs(DiscoveredInputsEvent event) {
+    ActionDumpWriter localWriter = writer;
+    if (localWriter != null) {
+      localWriter.enqueue(event);
+    }
+  }
+
   /** Record an action that didn't publish any SpawnExecutedEvents. */
   @Subscribe
   @AllowConcurrentEvents
@@ -401,11 +413,23 @@ private ExecutionGraph.Node toProto(SpawnExecutedEvent event) {
       SpawnMetrics metrics = spawnResult.getMetrics();
       spawnResult = null;
       long totalMillis = metrics.totalTime().toMillis();
+
+      long discoverInputsMillis = 0;
+      ActionInput firstOutput = getFirstOutput(spawn.getResourceOwner(), spawn.getOutputFiles());
+      Duration discoverInputsTime = outputToDiscoverInputsTime.get(firstOutput);
+      if (discoverInputsTime != null) {
+        // Remove this so we don't count it again later, if an action has multiple spawns.
+        outputToDiscoverInputsTime.remove(firstOutput);
+        discoverInputsMillis = discoverInputsTime.toMillis();
+        totalMillis += discoverInputsMillis;
+      }
+
       ExecutionGraph.Metrics.Builder metricsBuilder =
           ExecutionGraph.Metrics.newBuilder()
               .setStartTimestampMillis(startMillis)
               .setDurationMillis((int) totalMillis)
               .setFetchMillis((int) metrics.fetchTime().toMillis())
+              .setDiscoverInputsMillis((int) discoverInputsMillis)
               .setParseMillis((int) metrics.parseTime().toMillis())
               .setProcessMillis((int) metrics.executionWallTime().toMillis())
               .setQueueMillis((int) metrics.queueTime().toMillis())
@@ -544,6 +568,7 @@ private NodeInfo(int index, long finishMs) {
     private final BugReporter bugReporter;
     private final boolean localLockFreeOutputEnabled;
     private final Map<ActionInput, NodeInfo> outputToNode = new ConcurrentHashMap<>();
+    private final Map<ActionInput, Duration> outputToDiscoverInputsTime = new ConcurrentHashMap<>();
     private final DependencyInfo depType;
     private final AtomicInteger nextIndex = new AtomicInteger(0);
 
@@ -607,6 +632,20 @@ void enqueue(byte[] entry) {
       blockedMillis.addAndGet(sw.elapsed().toMillis());
     }
 
+    void enqueue(DiscoveredInputsEvent event) {
+      // The other times from SpawnMetrics are not needed. The only instance of
+      // DiscoveredInputsEvent sets only total and parse time, and to the same value.
+      var totalTime = event.getMetrics().totalTime();
+      var firstOutput = getFirstOutput(event.getAction(), event.getAction().getOutputs());
+      var sum = outputToDiscoverInputsTime.get(firstOutput);
+      if (sum != null) {
+        sum = sum.plus(totalTime);
+      } else {
+        sum = totalTime;
+      }
+      outputToDiscoverInputsTime.put(firstOutput, sum);
+    }
+
     void enqueue(Action action, long startMillis) {
       // This is here just to capture actions which don't have spawns. If we already know about
       // an output, don't also include it again.

src/main/protobuf/execution_graph.proto

@@ -79,6 +79,7 @@ message Metrics {
   int32 setup_millis = 8;
   int32 process_outputs_millis = 9;
   int32 queue_millis = 10;
+  int32 discover_inputs_millis = 14;
 
   // Total time spent on failed attempts.
   int32 retry_millis = 11;

src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphModuleTest.java

@@ -34,6 +34,7 @@
 import com.google.devtools.build.lib.actions.Artifact;
 import com.google.devtools.build.lib.actions.ArtifactRoot;
 import com.google.devtools.build.lib.actions.ArtifactRoot.RootType;
+import com.google.devtools.build.lib.actions.DiscoveredInputsEvent;
 import com.google.devtools.build.lib.actions.ExecutionGraph;
 import com.google.devtools.build.lib.actions.ResourceSet;
 import com.google.devtools.build.lib.actions.SimpleSpawn;
@@ -145,6 +146,57 @@ public void testOneSpawn() throws IOException {
     assertThat(nodes.get(0).getDependentIndexList()).isEmpty();
   }
 
+  @Test
+  public void testSpawnWithDiscoverInputs() throws IOException {
+    UUID uuid = UUID.randomUUID();
+    ByteArrayOutputStream buffer = new ByteArrayOutputStream();
+    Spawn spawn =
+        new SimpleSpawn(
+            new FakeOwnerWithPrimaryOutput(
+                "Mnemonic", "Progress message", "//foo", "output/foo/out"),
+            ImmutableList.of("cmd"),
+            ImmutableMap.of("env", "value"),
+            ImmutableMap.of("exec", "value"),
+            /* inputs= */ NestedSetBuilder.emptySet(Order.STABLE_ORDER),
+            /* outputs= */ ImmutableSet.of(createOutputArtifact("output/foo/out")),
+            ResourceSet.ZERO);
+    SpawnResult result =
+        new SpawnResult.Builder()
+            .setRunnerName("local")
+            .setStatus(Status.SUCCESS)
+            .setExitCode(0)
+            .setSpawnMetrics(
+                SpawnMetrics.Builder.forLocalExec()
+                    .setTotalTime(Duration.ofMillis(1234L))
+                    .setExecutionWallTime(Duration.ofMillis(2345L))
+                    .setProcessOutputsTime(Duration.ofMillis(3456L))
+                    .setParseTime(Duration.ofMillis(2000))
+                    .build())
+            .build();
+    startLogging(eventBus, uuid, buffer, DependencyInfo.NONE);
+    Instant startTimeInstant = Instant.ofEpochMilli(999888777L);
+    module.discoverInputs(
+        new DiscoveredInputsEvent(
+            SpawnMetrics.Builder.forOtherExec()
+                .setParseTime(Duration.ofMillis(987))
+                .setTotalTime(Duration.ofMillis(987))
+                .build(),
+            new ActionsTestUtil.NullAction(createOutputArtifact("output/foo/out")),
+            0));
+    module.spawnExecuted(new SpawnExecutedEvent(spawn, result, startTimeInstant));
+    module.buildComplete(
+        new BuildCompleteEvent(new BuildResult(startTimeInstant.toEpochMilli() + 1000)));
+
+    ImmutableList<ExecutionGraph.Node> nodes = parse(buffer);
+    ExecutionGraph.Metrics metrics = nodes.get(0).getMetrics();
+    assertThat(metrics.getDurationMillis()).isEqualTo(2221);
+    assertThat(metrics.getFetchMillis()).isEqualTo(0);
+    assertThat(metrics.getProcessMillis()).isEqualTo(2345);
+    assertThat(metrics.getProcessOutputsMillis()).isEqualTo(3456);
+    assertThat(metrics.getParseMillis()).isEqualTo(2000);
+    assertThat(metrics.getDiscoverInputsMillis()).isEqualTo(987);
+  }
+
   @Test
   public void actionDepsWithThreeSpawns() throws IOException {
     UUID uuid = UUID.randomUUID();