Add experimental option to do add local cpu usage values to the JSON profile.
RELNOTES: None
PiperOrigin-RevId: 208646319
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 0000000..2b64c12
--- /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 11f2896..abbf415 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 @@
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 @@
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 @@
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 @@
// activate profiler
profileStartTime = execStartTimeNanos;
+
+ if (enabledCpuUsageProfiling) {
+ cpuUsageThread = new CollectLocalCpuUsage();
+ cpuUsageThread.setDaemon(true);
+ cpuUsageThread.start();
+ }
}
/**
@@ -613,6 +624,18 @@
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 @@
}
}
- /** 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 @@
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 @@
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 0d244f4..93e06ec 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 @@
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 a729784..5e052a2 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 @@
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 4a32b2c..86c4581 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 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 044ae8c..448a21b 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 @@
@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 43d6bbc..468f6bb 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 @@
"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 a4b5424..4c18785 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 @@
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 @@
"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 @@
"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 @@
"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 @@
"testResilenceToNonDecreasingNanoTimes",
false,
badClock,
- initialNanoTime);
+ initialNanoTime,
+ /* enabledCpuUsageProfiling= */ false);
profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.INFO, "some task");
profiler.stop();
}
@@ -589,7 +607,8 @@
"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 @@
"basic test",
false,
BlazeClock.instance(),
- BlazeClock.instance().nanoTime());
+ BlazeClock.instance().nanoTime(),
+ /* enabledCpuUsageProfiling= */ false);
profiler.logSimpleTaskDuration(
Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
try {
