Add explicit execution_phase_time_in_ms to TimingMetrics.

PiperOrigin-RevId: 552459757
Change-Id: Iefd62dce7af2bf3c0a0802f90c3347bb2047989f

Author: joeleba

src/main/java/com/google/devtools/build/lib/buildeventstream/proto/build_event_stream.proto

@@ -965,6 +965,9 @@ message BuildMetrics {
   PackageMetrics package_metrics = 4;
 
   message TimingMetrics {
+    // For Skymeld,
+    // analysis_phase_time_in_ms + execution_phase_time_in_ms >= wall_time_in_ms
+    //
     // The CPU time in milliseconds consumed during this build.
     int64 cpu_time_in_ms = 1;
     // The elapsed wall time in milliseconds during this build.
@@ -973,6 +976,10 @@ message BuildMetrics {
     // When analysis and execution phases are interleaved, this measures the
     // elapsed time from the first analysis work to the last.
     int64 analysis_phase_time_in_ms = 3;
+    // The elapsed wall time in milliseconds during the execution phase.
+    // When analysis and execution phases are interleaved, this measures the
+    // elapsed time from the first action execution to the last.
+    int64 execution_phase_time_in_ms = 4;
   }
   TimingMetrics timing_metrics = 5;
 

src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java

@@ -99,6 +99,7 @@ class MetricsCollector {
   // TopLevelTargetExecutionStartedEvent. This AtomicBoolean is so that we only account for the
   // build once.
   private final AtomicBoolean buildAccountedFor;
+  private long executionStartMillis;
 
   @CanIgnoreReturnValue
   private MetricsCollector(
@@ -157,6 +158,10 @@ public void onAnalysisPhaseComplete(AnalysisPhaseCompleteEvent event) {
     }
   }
 
+  private void markExecutionPhaseStarted() {
+    executionStartMillis = BlazeClock.instance().currentTimeMillis();
+  }
+
   @SuppressWarnings("unused")
   @Subscribe
   public synchronized void logAnalysisGraphStats(AnalysisGraphStatsEvent event) {
@@ -175,13 +180,17 @@ public synchronized void logAnalysisGraphStats(AnalysisGraphStatsEvent event) {
   @SuppressWarnings("unused")
   @Subscribe
   public synchronized void logExecutionStartingEvent(ExecutionStartingEvent event) {
+    markExecutionPhaseStarted();
     numBuilds.getAndIncrement();
   }
 
+  // Skymeld-specific: we don't have an ExecutionStartingEvent for skymeld, so we have to use
+  // TopLevelTargetExecutionStartedEvent
   @Subscribe
-  public synchronized void accountForBuild(
+  public synchronized void handleExecutionPhaseStart(
       @SuppressWarnings("unused") TopLevelTargetPendingExecutionEvent event) {
     if (buildAccountedFor.compareAndSet(/*expectedValue=*/ false, /*newValue=*/ true)) {
+      markExecutionPhaseStarted();
       numBuilds.getAndIncrement();
     }
   }
@@ -255,6 +264,8 @@ public void actionResultReceived(ActionResultReceivedEvent event) {
   @SuppressWarnings("unused")
   @Subscribe
   public void onExecutionComplete(ExecutionFinishedEvent event) {
+    timingMetrics.setExecutionPhaseTimeInMs(
+        BlazeClock.instance().currentTimeMillis() - executionStartMillis);
     artifactMetrics
         .setSourceArtifactsRead(event.sourceArtifactsRead())
         .setOutputArtifactsSeen(event.outputArtifactsSeen())

src/test/java/com/google/devtools/build/lib/metrics/MetricsCollectorTest.java

@@ -519,6 +519,13 @@ public void testAnalysisTimeInMs() throws Exception {
     assertThat(buildMetrics.getTimingMetrics().getAnalysisPhaseTimeInMs()).isGreaterThan(0);
   }
 
+  @Test
+  public void testExecutionTimeInMs() throws Exception {
+    buildTarget("//foo:foo");
+    BuildMetrics buildMetrics = buildMetricsEventListener.event.getBuildMetrics();
+    assertThat(buildMetrics.getTimingMetrics().getExecutionPhaseTimeInMs()).isGreaterThan(0);
+  }
+
   @Test
   public void testUsedHeapSizePostBuild() throws Exception {
     // TODO(bazel-team): Fix recording used heap size on Windows.