Add experimental option to do add local cpu usage values to the JSON profile.

RELNOTES: None
PiperOrigin-RevId: 208646319

8 files changed, 183 insertions, 30 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/profiler/CollectLocalCpuUsage.java b/src/main/java/com/google/devtools/build/lib/profiler/CollectLocalCpuUsage.java
new file mode 100644
index 0000000000..2b64c128b8
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/profiler/CollectLocalCpuUsage.java
@@ -0,0 +1,77 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package com.google.devtools.build.lib.profiler;
+
+import com.google.common.base.Preconditions;
+import com.sun.management.OperatingSystemMXBean;
+import java.lang.management.ManagementFactory;
+import java.util.concurrent.TimeUnit;
+
+/** Thread to collect local cpu usage data and log into JSON profile. */
+public class CollectLocalCpuUsage extends Thread {
+  // TODO(twerth): Make these configurable.
+  private static final long BUCKET_SIZE_MILLIS = 1000;
+  private static final long LOCAL_CPU_SLEEP_MILLIS = 200;
+
+  private volatile boolean stopCpuUsage;
+  private long cpuProfileStartMillis;
+  private CpuUsageTimeSeries localCpuUsage;
+
+  @Override
+  public void run() {
+    stopCpuUsage = false;
+    cpuProfileStartMillis = System.currentTimeMillis();
+    localCpuUsage = new CpuUsageTimeSeries(cpuProfileStartMillis, BUCKET_SIZE_MILLIS);
+    OperatingSystemMXBean bean =
+        (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();
+    long previousTimeMillis = System.currentTimeMillis();
+    long previousCpuTimeMillis = TimeUnit.NANOSECONDS.toMillis(bean.getProcessCpuTime());
+    while (!stopCpuUsage) {
+      try {
+        Thread.sleep(LOCAL_CPU_SLEEP_MILLIS);
+      } catch (InterruptedException e) {
+        return;
+      }
+      long nextTimeMillis = System.currentTimeMillis();
+      long nextCpuTimeMillis = TimeUnit.NANOSECONDS.toMillis(bean.getProcessCpuTime());
+      double deltaMillis = nextTimeMillis - previousTimeMillis;
+      double cpuLevel = (nextCpuTimeMillis - previousCpuTimeMillis) / deltaMillis;
+      localCpuUsage.addRange(previousTimeMillis, nextTimeMillis, cpuLevel);
+      previousTimeMillis = nextTimeMillis;
+      previousCpuTimeMillis = nextCpuTimeMillis;
+    }
+  }
+
+  public void stopCollecting() {
+    Preconditions.checkArgument(!stopCpuUsage);
+    stopCpuUsage = true;
+  }
+
+  public void logCollectedData() {
+    Preconditions.checkArgument(stopCpuUsage);
+    long currentTimeNanos = System.nanoTime();
+    long currentTimeMillis = System.currentTimeMillis();
+    int len = (int) ((currentTimeMillis - cpuProfileStartMillis) / BUCKET_SIZE_MILLIS) + 1;
+    double[] localCpuUsageValues = localCpuUsage.toDoubleArray(len);
+    Profiler profiler = Profiler.instance();
+    for (int i = 0; i < len; i++) {
+      long timeMillis = cpuProfileStartMillis + i * BUCKET_SIZE_MILLIS;
+      long timeNanos =
+          TimeUnit.MILLISECONDS.toNanos(timeMillis - currentTimeMillis) + currentTimeNanos;
+      profiler.logEventAtTime(
+          timeNanos, ProfilerTask.LOCAL_CPU_USAGE, String.valueOf(localCpuUsageValues[i]));
+    }
+    localCpuUsage = null;
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
index 11f28965b3..abbf415c94 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
@@ -15,6 +15,7 @@ package com.google.devtools.build.lib.profiler;
 
 import static com.google.devtools.build.lib.profiler.ProfilerTask.TASK_COUNT;
 
+import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.Preconditions;
 import com.google.common.base.Predicate;
 import com.google.common.collect.ImmutableList;
@@ -473,6 +474,9 @@ public final class Profiler {
 
   private final StatRecorder[] tasksHistograms = new StatRecorder[ProfilerTask.values().length];
 
+  /** Thread that collects local cpu usage data (if enabled). */
+  private CollectLocalCpuUsage cpuUsageThread;
+
   private Profiler() {
     initHistograms();
     for (ProfilerTask task : ProfilerTask.values()) {
@@ -550,7 +554,8 @@ public final class Profiler {
       String comment,
       boolean recordAllDurations,
       Clock clock,
-      long execStartTimeNanos)
+      long execStartTimeNanos,
+      boolean enabledCpuUsageProfiling)
       throws IOException {
     Preconditions.checkState(!isActive(), "Profiler already active");
     initHistograms();
@@ -585,6 +590,12 @@ public final class Profiler {
 
     // activate profiler
     profileStartTime = execStartTimeNanos;
+
+    if (enabledCpuUsageProfiling) {
+      cpuUsageThread = new CollectLocalCpuUsage();
+      cpuUsageThread.setDaemon(true);
+      cpuUsageThread.start();
+    }
   }
 
   /**
@@ -613,6 +624,18 @@ public final class Profiler {
     if (!isActive()) {
       return;
     }
+
+    if (cpuUsageThread != null) {
+      cpuUsageThread.stopCollecting();
+      try {
+        cpuUsageThread.join();
+      } catch (InterruptedException e) {
+        Thread.currentThread().interrupt();
+      }
+      cpuUsageThread.logCollectedData();
+      cpuUsageThread = null;
+    }
+
     // Log a final event to update the duration of ProfilePhase.FINISH.
     logEvent(ProfilerTask.INFO, "Finishing");
     FileWriter writer = writerRef.getAndSet(null);
@@ -749,13 +772,19 @@ public final class Profiler {
     }
   }
 
-  /** Used to log "events" - tasks with zero duration. */
-  void logEvent(ProfilerTask type, String description) {
+  /** Used to log "events" happening at a specific time - tasks with zero duration. */
+  public void logEventAtTime(long atTimeNanos, ProfilerTask type, String description) {
     if (isActive() && isProfiling(type)) {
-      logTask(clock.nanoTime(), 0, type, description);
+      logTask(atTimeNanos, 0, type, description);
     }
   }
 
+  /** Used to log "events" - tasks with zero duration. */
+  @VisibleForTesting
+  void logEvent(ProfilerTask type, String description) {
+    logEventAtTime(clock.nanoTime(), type, description);
+  }
+
   /**
    * Records the beginning of a task as specified, and returns a {@link SilentCloseable} instance
    * that ends the task. This lets the system do the work of ending the task, with the compiler
@@ -1059,9 +1088,6 @@ public final class Profiler {
           writer.endObject();
 
           while ((data = queue.take()) != POISON_PILL) {
-            if (data.duration == 0 && data.type != ProfilerTask.THREAD_NAME) {
-              continue;
-            }
             if (data.type == ProfilerTask.THREAD_NAME) {
               writer.setIndent("  ");
               writer.beginObject();
@@ -1079,6 +1105,27 @@ public final class Profiler {
               writer.endObject();
               continue;
             }
+            if (data.type == ProfilerTask.LOCAL_CPU_USAGE) {
+              writer.setIndent("  ");
+              writer.beginObject();
+              writer.setIndent("");
+              writer.name("name").value(data.type.description);
+              writer.name("ph").value("C");
+              writer
+                  .name("ts")
+                  .value(
+                      TimeUnit.NANOSECONDS.toMicros(data.startTimeNanos - profileStartTimeNanos));
+              writer.name("pid").value(1);
+              writer.name("tid").value(data.threadId);
+              writer.name("args");
+
+              writer.beginObject();
+              writer.name("cpu").value(data.description);
+              writer.endObject();
+
+              writer.endObject();
+              continue;
+            }
             String eventType = data.duration == 0 ? "i" : "X";
             writer.setIndent("  ");
             writer.beginObject();
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java b/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java
index 0d244f400c..93e06ec8c7 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java
@@ -76,7 +76,7 @@ public enum ProfilerTask {
   CRITICAL_PATH("critical path", 0x666699),
   CRITICAL_PATH_COMPONENT("critical path component", 0x666699),
   HANDLE_GC_NOTIFICATION("gc notification", 0x996633),
-  __INCLUSION_LOOKUP("inclusion lookup", 0x000000), // unused
+  LOCAL_CPU_USAGE("cpu counters", 0x000000),
   __INCLUSION_PARSE("inclusion parse", 0x000000), // unused
   __PROCESS_SCAN("process scan", 0x000000), // unused
   __LOOP_OUTPUT_ARTIFACTS("loop output artifacts"), // unused
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
index a729784a4c..5e052a245b 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
@@ -313,13 +313,11 @@ public final class BlazeRuntime {
             format,
             String.format(
                 "%s profile for %s at %s, build ID: %s",
-                getProductName(),
-                workspace.getOutputBase(),
-                new Date(),
-                buildID),
+                getProductName(), workspace.getOutputBase(), new Date(), buildID),
             recordFullProfilerData,
             clock,
-            execStartTimeNanos);
+            execStartTimeNanos,
+            options.enableCpuUsageProfiling);
         // Instead of logEvent() we're calling the low level function to pass the timings we took in
         // the launcher. We're setting the INIT phase marker so that it follows immediately the
         // LAUNCH phase.
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java b/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
index 4a32b2c405..86c4581304 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
@@ -212,6 +212,14 @@ public class CommonCommandOptions extends OptionsBase {
   public boolean postProfileStartedEvent;
 
   @Option(
+      name = "experimental_profile_cpu_usage",
+      defaultValue = "false",
+      documentationCategory = OptionDocumentationCategory.LOGGING,
+      effectTags = {OptionEffectTag.AFFECTS_OUTPUTS, OptionEffectTag.BAZEL_MONITORING},
+      help = "If set, Bazel will measure cpu usage and add it to the JSON profile.")
+  public boolean enableCpuUsageProfiling;
+
+  @Option(
       name = "profile",
       defaultValue = "null",
       documentationCategory = OptionDocumentationCategory.LOGGING,
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java b/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java
index 044ae8c0d4..448a21baca 100644
--- a/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java
+++ b/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java
@@ -27,14 +27,16 @@ public class AutoProfilerBenchmark {
 
   @BeforeExperiment
   void startProfiler() throws Exception {
-    Profiler.instance().start(
-        ProfiledTaskKinds.ALL,
-        new InMemoryFileSystem().getPath("/out.dat").getOutputStream(),
-        Profiler.Format.BINARY_BAZEL_FORMAT,
-        "benchmark",
-        false,
-        BlazeClock.instance(),
-        BlazeClock.instance().nanoTime());
+    Profiler.instance()
+        .start(
+            ProfiledTaskKinds.ALL,
+            new InMemoryFileSystem().getPath("/out.dat").getOutputStream(),
+            Profiler.Format.BINARY_BAZEL_FORMAT,
+            "benchmark",
+            false,
+            BlazeClock.instance(),
+            BlazeClock.instance().nanoTime(),
+            /* enabledCpuUsageProfiling= */ false);
   }
 
   @BeforeExperiment
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
index 43d6bbc2d1..468f6bba42 100644
--- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
+++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
@@ -258,7 +258,8 @@ public class ProfilerChartTest extends FoundationTestCase {
           "basic test",
           false,
           BlazeClock.instance(),
-          BlazeClock.instance().nanoTime());
+          BlazeClock.instance().nanoTime(),
+          /* enabledCpuUsageProfiling= */ false);
 
       // Write from multiple threads to generate multiple rows in the chart.
       for (int i = 0; i < noOfRows; i++) {
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
index a4b5424c1a..4c1878577e 100644
--- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
+++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
@@ -79,13 +79,27 @@ public class ProfilerTest {
       throws IOException {
     ByteArrayOutputStream buffer = new ByteArrayOutputStream();
     profiler.start(
-        kinds, buffer, format, "test", false, BlazeClock.instance(), BlazeClock.nanoTime());
+        kinds,
+        buffer,
+        format,
+        "test",
+        false,
+        BlazeClock.instance(),
+        BlazeClock.nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
     return buffer;
   }
 
   private void startUnbuffered(ProfiledTaskKinds kinds) throws IOException {
     profiler.start(
-        kinds, null, null, "test", false, BlazeClock.instance(), BlazeClock.nanoTime());
+        kinds,
+        null,
+        null,
+        "test",
+        false,
+        BlazeClock.instance(),
+        BlazeClock.nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
   }
 
   @Test
@@ -183,7 +197,8 @@ public class ProfilerTest {
         "basic test",
         true,
         BlazeClock.instance(),
-        BlazeClock.instance().nanoTime());
+        BlazeClock.instance().nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
     try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "action task")) {
       // Next task takes less than 10 ms but should be recorded anyway.
       clock.advanceMillis(1);
@@ -212,7 +227,8 @@ public class ProfilerTest {
         "test",
         true,
         BlazeClock.instance(),
-        BlazeClock.instance().nanoTime());
+        BlazeClock.instance().nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
     profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
     profiler.logSimpleTask(20000, 30000, ProfilerTask.REMOTE_EXECUTION, "remote execution");
 
@@ -320,7 +336,8 @@ public class ProfilerTest {
         "test",
         true,
         BlazeClock.instance(),
-        BlazeClock.instance().nanoTime());
+        BlazeClock.instance().nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
     profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
 
     assertThat(ProfilerTask.VFS_STAT.collectsSlowestInstances()).isTrue();
@@ -539,7 +556,8 @@ public class ProfilerTest {
         "testResilenceToNonDecreasingNanoTimes",
         false,
         badClock,
-        initialNanoTime);
+        initialNanoTime,
+        /* enabledCpuUsageProfiling= */ false);
     profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.INFO, "some task");
     profiler.stop();
   }
@@ -589,7 +607,8 @@ public class ProfilerTest {
         "basic test",
         false,
         BlazeClock.instance(),
-        BlazeClock.instance().nanoTime());
+        BlazeClock.instance().nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
     profiler.logSimpleTaskDuration(
         Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
     try {
@@ -615,7 +634,8 @@ public class ProfilerTest {
         "basic test",
         false,
         BlazeClock.instance(),
-        BlazeClock.instance().nanoTime());
+        BlazeClock.instance().nanoTime(),
+        /* enabledCpuUsageProfiling= */ false);
     profiler.logSimpleTaskDuration(
         Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
     try {