diff options
Diffstat (limited to 'src/main')
5 files changed, 143 insertions, 13 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, |