From f4fbbd653822ef7306f60144515e7ef551b2d39b Mon Sep 17 00:00:00 2001 From: twerth Date: Thu, 4 Feb 2021 06:33:17 -0800 Subject: [PATCH] Also collect server heap size during profiling and log it to the JSON profile. PiperOrigin-RevId: 355613771 --- .../google/devtools/build/lib/profiler/BUILD | 2 +- ...ge.java => CollectLocalResourceUsage.java} | 52 ++++++++++++++----- .../devtools/build/lib/profiler/Profiler.java | 26 +++++++--- .../build/lib/profiler/ProfilerTask.java | 3 +- 4 files changed, 60 insertions(+), 23 deletions(-) rename src/main/java/com/google/devtools/build/lib/profiler/{CollectLocalCpuUsage.java => CollectLocalResourceUsage.java} (62%) diff --git a/src/main/java/com/google/devtools/build/lib/profiler/BUILD b/src/main/java/com/google/devtools/build/lib/profiler/BUILD index f192c7719bed0d..13afb45d222d05 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/BUILD +++ b/src/main/java/com/google/devtools/build/lib/profiler/BUILD @@ -12,7 +12,7 @@ java_library( name = "profiler", srcs = [ "AutoProfiler.java", - "CollectLocalCpuUsage.java", + "CollectLocalResourceUsage.java", "MemoryProfiler.java", "MetricData.java", "PredicateBasedStatRecorder.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/CollectLocalResourceUsage.java similarity index 62% rename from src/main/java/com/google/devtools/build/lib/profiler/CollectLocalCpuUsage.java rename to src/main/java/com/google/devtools/build/lib/profiler/CollectLocalResourceUsage.java index ad4bf80255b217..37c61e02f67482 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/CollectLocalCpuUsage.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/CollectLocalResourceUsage.java @@ -18,21 +18,25 @@ import com.google.errorprone.annotations.concurrent.GuardedBy; import com.sun.management.OperatingSystemMXBean; import java.lang.management.ManagementFactory; +import java.lang.management.MemoryMXBean; import java.time.Duration; import java.util.concurrent.TimeUnit; -/** Thread to collect local cpu usage data and log into JSON profile. */ -public class CollectLocalCpuUsage extends Thread { +/** Thread to collect local resource usage data and log into JSON profile. */ +public class CollectLocalResourceUsage extends Thread { // TODO(twerth): Make these configurable. private static final Duration BUCKET_DURATION = Duration.ofSeconds(1); private static final long LOCAL_CPU_SLEEP_MILLIS = 200; - private volatile boolean stopCpuUsage; + private volatile boolean stopLocalUsageCollection; private volatile boolean profilingStarted; @GuardedBy("this") private TimeSeries localCpuUsage; + @GuardedBy("this") + private TimeSeries localMemoryUsage; + private Stopwatch stopwatch; @Override @@ -42,26 +46,37 @@ public void run() { localCpuUsage = new TimeSeries( /* startTimeMillis= */ stopwatch.elapsed().toMillis(), BUCKET_DURATION.toMillis()); + localMemoryUsage = + new TimeSeries( + /* startTimeMillis= */ stopwatch.elapsed().toMillis(), BUCKET_DURATION.toMillis()); } - OperatingSystemMXBean bean = + OperatingSystemMXBean osBean = (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean(); + MemoryMXBean memoryBean = ManagementFactory.getMemoryMXBean(); Duration previousElapsed = stopwatch.elapsed(); - long previousCpuTimeNanos = bean.getProcessCpuTime(); + long previousCpuTimeNanos = osBean.getProcessCpuTime(); profilingStarted = true; - while (!stopCpuUsage) { + while (!stopLocalUsageCollection) { try { Thread.sleep(LOCAL_CPU_SLEEP_MILLIS); } catch (InterruptedException e) { return; } Duration nextElapsed = stopwatch.elapsed(); - long nextCpuTimeNanos = bean.getProcessCpuTime(); + long nextCpuTimeNanos = osBean.getProcessCpuTime(); + long memoryUsage = + memoryBean.getHeapMemoryUsage().getUsed() + memoryBean.getNonHeapMemoryUsage().getUsed(); double deltaNanos = nextElapsed.minus(previousElapsed).toNanos(); double cpuLevel = (nextCpuTimeNanos - previousCpuTimeNanos) / deltaNanos; synchronized (this) { if (localCpuUsage != null) { localCpuUsage.addRange(previousElapsed.toMillis(), nextElapsed.toMillis(), cpuLevel); } + if (localMemoryUsage != null) { + long memoryUsageMb = memoryUsage / (1024 * 1024); + localMemoryUsage.addRange( + previousElapsed.toMillis(), nextElapsed.toMillis(), memoryUsageMb); + } } previousElapsed = nextElapsed; previousCpuTimeNanos = nextCpuTimeNanos; @@ -69,8 +84,8 @@ public void run() { } public void stopCollecting() { - Preconditions.checkArgument(!stopCpuUsage); - stopCpuUsage = true; + Preconditions.checkArgument(!stopLocalUsageCollection); + stopLocalUsageCollection = true; interrupt(); } @@ -78,18 +93,27 @@ public synchronized void logCollectedData() { if (!profilingStarted) { return; } - Preconditions.checkArgument(stopCpuUsage); + Preconditions.checkArgument(stopLocalUsageCollection); long endTimeNanos = System.nanoTime(); long elapsedNanos = stopwatch.elapsed(TimeUnit.NANOSECONDS); long startTimeNanos = endTimeNanos - elapsedNanos; int len = (int) (elapsedNanos / BUCKET_DURATION.toNanos()) + 1; - double[] localCpuUsageValues = localCpuUsage.toDoubleArray(len); Profiler profiler = Profiler.instance(); + + logCollectedData(profiler, localCpuUsage, ProfilerTask.LOCAL_CPU_USAGE, startTimeNanos, len); + localCpuUsage = null; + + logCollectedData( + profiler, localMemoryUsage, ProfilerTask.LOCAL_MEMORY_USAGE, startTimeNanos, len); + localMemoryUsage = null; + } + + private static void logCollectedData( + Profiler profiler, TimeSeries timeSeries, ProfilerTask type, long startTimeNanos, int len) { + double[] localCpuUsageValues = timeSeries.toDoubleArray(len); for (int i = 0; i < len; i++) { long eventTimeNanos = startTimeNanos + i * BUCKET_DURATION.toNanos(); - profiler.logEventAtTime( - eventTimeNanos, ProfilerTask.LOCAL_CPU_USAGE, String.valueOf(localCpuUsageValues[i])); + profiler.logEventAtTime(eventTimeNanos, type, 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 3f756788455fa4..1e332e870f270e 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 @@ -256,7 +256,7 @@ Iterable getSlowestTasks() { private final StatRecorder[] tasksHistograms = new StatRecorder[ProfilerTask.values().length]; /** Thread that collects local cpu usage data (if enabled). */ - private CollectLocalCpuUsage cpuUsageThread; + private CollectLocalResourceUsage cpuUsageThread; private TimeSeries actionCountTimeSeries; private long actionCountStartTime; @@ -419,7 +419,7 @@ public synchronized void start( profileCpuStartTime = getProcessCpuTime(); if (enabledCpuUsageProfiling) { - cpuUsageThread = new CollectLocalCpuUsage(); + cpuUsageThread = new CollectLocalResourceUsage(); cpuUsageThread.setDaemon(true); cpuUsageThread.start(); } @@ -1097,6 +1097,7 @@ public void run() { } if (data.type == ProfilerTask.LOCAL_CPU_USAGE + || data.type == ProfilerTask.LOCAL_MEMORY_USAGE || data.type == ProfilerTask.ACTION_COUNTS) { // Skip counts equal to zero. They will show up as a thin line in the profile. if ("0.0".equals(data.description)) { @@ -1106,6 +1107,10 @@ public void run() { writer.beginObject(); writer.setIndent(""); writer.name("name").value(data.type.description); + if (data.type == ProfilerTask.LOCAL_MEMORY_USAGE) { + // Make this more distinct in comparison to other counter colors. + writer.name("cname").value("olive"); + } writer.name("ph").value("C"); writer .name("ts") @@ -1116,12 +1121,19 @@ public void run() { writer.name("args"); writer.beginObject(); - if (data.type == ProfilerTask.LOCAL_CPU_USAGE) { - writer.name("cpu").value(data.description); - } else { - writer.name("action").value(data.description); + switch (data.type) { + case LOCAL_CPU_USAGE: + writer.name("cpu").value(data.description); + break; + case LOCAL_MEMORY_USAGE: + writer.name("memory").value(data.description); + break; + case ACTION_COUNTS: + writer.name("action").value(data.description); + break; + default: + // won't happen } - writer.endObject(); writer.endObject(); 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 98b914fa09f130..287a9937a7bcde 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 @@ -64,8 +64,9 @@ public enum ProfilerTask { CRITICAL_PATH("critical path"), CRITICAL_PATH_COMPONENT("critical path component"), HANDLE_GC_NOTIFICATION("gc notification"), - LOCAL_CPU_USAGE("cpu counters"), ACTION_COUNTS("action counters"), + LOCAL_CPU_USAGE("cpu counters"), + LOCAL_MEMORY_USAGE("memory counters"), STARLARK_PARSER("Starlark Parser", Threshold.FIFTY_MILLIS), STARLARK_USER_FN("Starlark user function call", Threshold.FIFTY_MILLIS), STARLARK_BUILTIN_FN("Starlark builtin function call", Threshold.FIFTY_MILLIS),