From d12db5975687a87b6d36543747234200d0cdc3b5 Mon Sep 17 00:00:00 2001 From: twerth Date: Tue, 14 Aug 2018 07:53:40 -0700 Subject: Add experimental option to do add local cpu usage values to the JSON profile. RELNOTES: None PiperOrigin-RevId: 208646319 --- .../build/lib/profiler/CollectLocalCpuUsage.java | 77 ++++++++++++++++++++++ .../devtools/build/lib/profiler/Profiler.java | 61 +++++++++++++++-- .../devtools/build/lib/profiler/ProfilerTask.java | 2 +- .../devtools/build/lib/runtime/BlazeRuntime.java | 8 +-- .../build/lib/runtime/CommonCommandOptions.java | 8 +++ .../build/lib/profiler/AutoProfilerBenchmark.java | 18 ++--- .../build/lib/profiler/ProfilerChartTest.java | 3 +- .../devtools/build/lib/profiler/ProfilerTest.java | 36 +++++++--- 8 files changed, 183 insertions(+), 30 deletions(-) create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/CollectLocalCpuUsage.java 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 @@ -211,6 +211,14 @@ public class CommonCommandOptions extends OptionsBase { help = "If set, Bazel will post the ProfilerStartedEvent including the path to the profile.") 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", 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 { -- cgit v1.2.3