Report CPU and wall times in profiler output for build commands again.

This was broken in bazelbuild@cb42a1d. The reason is that MetricsCollector assumed that the profiler was active while calling finishTimingMetrics(), which used to be the case before that change. However, that change made finishTimingMetrics() be called in CommandPrecompleteEvent and (somewhat confusingly) BuildSummaryStatsModule shuts down the profiler in BuildCompleteEvent, which happens before.

Ideally, we'd shut down the profiler at the last minute, but we can't do that because we publish the profiler data to the BEP, which in turn shuts down in BuildCompleteEvent. So we must shut down the profiler in BuildCompleteEvent, but that doesn't happen on non-build commands so we must also shut it down some place that is called on every command. This of course means that we lose profiler events between BuildCompleteEvent and the actual end of the command.

The profiler is changed so that timing data is available after .stop(), which makes MetricsCollector work again.

RELNOTES: None.
PiperOrigin-RevId: 671727112
Change-Id: Ibf336a7a387449a3edbaffb3d399e5b5e9ed0ff4

Author: lberki

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

@@ -217,7 +217,7 @@ public synchronized void handleExecutionPhaseStart(
   public void onSomeExecutionStarted(SomeExecutionStartedEvent event) {
     if (event.countedInExecutionTime()) {
       if (executionStarted.compareAndSet(false, true)) {
-        Duration elapsedWallTime = Profiler.elapsedTimeMaybe();
+        Duration elapsedWallTime = Profiler.getProfileElapsedTime();
         if (elapsedWallTime != null) {
           timingMetrics.setActionsExecutionStartInMs(elapsedWallTime.toMillis());
         }
@@ -490,11 +490,11 @@ private CumulativeMetrics createCumulativeMetrics() {
   }
 
   private TimingMetrics finishTimingMetrics() {
-    Duration elapsedWallTime = Profiler.elapsedTimeMaybe();
+    Duration elapsedWallTime = Profiler.getProfileElapsedTime();
     if (elapsedWallTime != null) {
       timingMetrics.setWallTimeInMs(elapsedWallTime.toMillis());
     }
-    Duration cpuTime = Profiler.getProcessCpuTimeMaybe();
+    Duration cpuTime = Profiler.getServerProcessCpuTime();
     if (cpuTime != null) {
       timingMetrics.setCpuTimeInMs(cpuTime.toMillis());
     }

src/main/java/com/google/devtools/build/lib/profiler/Profiler.java

@@ -17,6 +17,7 @@
 import static com.google.common.base.Preconditions.checkState;
 
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Preconditions;
 import com.google.common.base.Predicate;
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableSet;
@@ -306,9 +307,12 @@ ImmutableList<SlowTask> getSlowestTasks() {
 
   private Clock clock;
   private Set<ProfilerTask> profiledTasks;
-  private volatile long profileStartTime;
+  private volatile boolean active = false;
   private volatile boolean recordAllDurations = false;
-  private Duration profileCpuStartTime;
+  private Duration profileCpuStartTime = Duration.ZERO;
+  private Duration profileCpuEndTime = Duration.ZERO;
+  private Duration profileStartTime = Duration.ZERO;
+  private Duration profileEndTime = Duration.ZERO;
 
   /**
    * The reference to the current writer, if any. If the referenced writer is null, then disk writes
@@ -376,7 +380,8 @@ private void initHistograms() {
   // stop instead? However, this is currently only called from one location in a module, and that
   // can't call stop itself. What to do?
   public synchronized ImmutableList<StatRecorder> getTasksHistograms() {
-    return isActive() ? ImmutableList.copyOf(tasksHistograms) : ImmutableList.of();
+    Preconditions.checkState(isActive());
+    return ImmutableList.copyOf(tasksHistograms);
   }
 
   public static Profiler instance() {
@@ -393,14 +398,12 @@ public static long nanoTimeMaybe() {
     return -1;
   }
 
-  // Returns the elapsed wall clock time since the profile has been started or null if inactive.
-  @Nullable
-  public static Duration elapsedTimeMaybe() {
-    if (instance.isActive()) {
-      return Duration.ofNanos(instance.clock.nanoTime())
-          .minus(Duration.ofNanos(instance.profileStartTime));
-    }
-    return null;
+  // Returns the elapsed wall clock time since the profile has been started.
+  public static Duration getProfileElapsedTime() {
+    Duration endTime =
+        instance.isActive() ? Duration.ofNanos(instance.clock.nanoTime()) : instance.profileEndTime;
+
+    return endTime.minus(instance.profileStartTime);
   }
 
   private static Duration getProcessCpuTime() {
@@ -409,13 +412,10 @@ private static Duration getProcessCpuTime() {
     return Duration.ofNanos(bean.getProcessCpuTime());
   }
 
-  // Returns the CPU time since the profile has been started or null if inactive.
-  @Nullable
-  public static Duration getProcessCpuTimeMaybe() {
-    if (instance().isActive()) {
-      return getProcessCpuTime().minus(instance().profileCpuStartTime);
-    }
-    return null;
+  // Returns the CPU time since the profile has been started.
+  public static Duration getServerProcessCpuTime() {
+    Duration cpuEndTime = instance.isActive() ? getProcessCpuTime() : instance.profileCpuEndTime;
+    return cpuEndTime.minus(instance.profileCpuStartTime);
   }
 
   /**
@@ -447,7 +447,8 @@ public synchronized void start(
       boolean collectTaskHistograms,
       LocalResourceCollector localResourceCollector)
       throws IOException {
-    checkState(!isActive(), "Profiler already active");
+    checkState(!active, "Profiler already active");
+
     initHistograms();
 
     this.profiledTasks = profiledTasks.isEmpty() ? profiledTasks : EnumSet.copyOf(profiledTasks);
@@ -484,8 +485,9 @@ public synchronized void start(
     this.writerRef.set(writer);
 
     // Activate profiler.
-    profileStartTime = execStartTimeNanos;
+    profileStartTime = Duration.ofNanos(execStartTimeNanos);
     profileCpuStartTime = getProcessCpuTime();
+    active = true;
 
     this.localResourceCollector = localResourceCollector;
     // Start collecting Bazel and system-wide CPU metric collection.
@@ -553,24 +555,41 @@ private boolean hasNonZeroValues(Map<ProfilerTask, double[]> countersSeriesMap)
    * will no longer be recorded in the profile.
    */
   public synchronized void stop() throws IOException {
-    if (!isActive()) {
+    if (!active) {
       return;
     }
 
     collectActionCounts();
-
     localResourceCollector.stop();
 
     // Log a final event to update the duration of ProfilePhase.FINISH.
     logEvent(ProfilerTask.INFO, "Finishing");
-    JsonTraceFileWriter writer = writerRef.getAndSet(null);
-    if (writer != null) {
-      writer.shutdown();
-      writer = null;
+    try {
+      JsonTraceFileWriter writer = writerRef.getAndSet(null);
+      if (writer != null) {
+        writer.shutdown();
+        writer = null;
+      }
+    } finally {
+      profileCpuEndTime = getProcessCpuTime();
+      profileEndTime = Duration.ofNanos(clock.nanoTime());
+      active = false;
     }
+  }
+
+  /**
+   * Clears the records the profiler instance keeps.
+   *
+   * <p>Should always be called between a {@link #stop()} and a subsequent {@link #start}.
+   */
+  public synchronized void clear() {
+    Preconditions.checkState(!active);
+
     Arrays.fill(tasksHistograms, null);
-    profileStartTime = 0L;
-    profileCpuStartTime = null;
+    profileStartTime = Duration.ZERO;
+    profileEndTime = Duration.ZERO;
+    profileCpuStartTime = Duration.ZERO;
+    profileCpuEndTime = Duration.ZERO;
 
     for (SlowestTaskAggregator aggregator : slowestTasks) {
       if (aggregator != null) {
@@ -583,7 +602,7 @@ public synchronized void stop() throws IOException {
 
   /** Returns true iff profiling is currently enabled. */
   public boolean isActive() {
-    return profileStartTime != 0L;
+    return active;
   }
 
   public boolean isProfiling(ProfilerTask type) {

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

@@ -729,12 +729,14 @@ private BlazeCommandResult execExclusively(
 
       try {
         Profiler.instance().stop();
-        MemoryProfiler.instance().stop();
       } catch (IOException e) {
         env.getReporter()
             .handle(Event.error("Error while writing profile file: " + e.getMessage()));
       }
 
+      Profiler.instance().clear();
+      MemoryProfiler.instance().stop();
+
       // Swallow IOException, as we are already in a finally clause
       Flushables.flushQuietly(outErr.getOutputStream());
       Flushables.flushQuietly(outErr.getErrorStream());

src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java

@@ -64,6 +64,7 @@ public final class ProfilerTest {
   @Before
   public void setManualClock() {
     BlazeClock.setClock(clock);
+    profiler.clear();
   }
 
   @AfterClass
@@ -732,21 +733,6 @@ public long nanoTime() {
     profiler.stop();
   }
 
-  /** Checks that the histograms are cleared in the stop call. */
-  @Test
-  public void testEmptyTaskHistograms() throws Exception {
-    startUnbuffered(getAllProfilerTasks());
-    profiler.logSimpleTaskDuration(
-        Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
-    for (StatRecorder recorder : profiler.tasksHistograms) {
-      assertThat(recorder).isNotNull();
-    }
-    profiler.stop();
-    for (StatRecorder recorder : profiler.tasksHistograms) {
-      assertThat(recorder).isNull();
-    }
-  }
-
   @Test
   public void testTaskHistograms() throws Exception {
     startUnbuffered(getAllProfilerTasks());

src/test/shell/integration/build_event_stream_test.sh

@@ -1478,9 +1478,12 @@ EOF
   chmod +x a/a.sh
 
   bazel build --build_event_text_file=bep.txt //a:a || fail "build failed"
+
   assert_contains "^build_metrics {" bep.txt
+  assert_contains "cpu_time_in_ms: " bep.txt
 
-  bazel test --build_event_text_file=bep.txt //a:a || fail "build failed"
+  # Check if null builds still have build metrics
+  bazel build --build_event_text_file=bep.txt //a:a || fail "build failed"
   assert_contains "^build_metrics {" bep.txt
 }