New allocation profiler
Vladimir Sitnikov
sitnikov.vladimir at gmail.com
Wed Apr 15 21:39:56 UTC 2015
>Please start a separate thread.
Please, nooo. I should have silently fixed that (see [1])
I beg on your forgiveness here since the fix touches pretty much the
same source file (see [2]).
Please review alloc.rate being added to GCProfiler.
Side fixes: typo in Profiler.java and churn.norm calculation.
[1]: I know I should not
[2]: Real reason is I have no idea how interactive rebase (i.e. commit
split & reorder) works in mercurial (does it?). I wish I converted the
repo to git at the very start.
Vladimir
-------------- next part --------------
# HG changeset patch
# User Vladimir Sitnikov <sitnikov.vladimir at gmail.com>
# Date 1428845687 -10800
# Sun Apr 12 16:34:47 2015 +0300
# Node ID 913c4e1341a64e272bb52c9280c27993c9177441
# Parent 1898f77c754c84e33da6b74b4e913f009cd27841
Add allocation profiling to -prof gc. The implementation is based on ThreadMXBean.getThreadAllocatedBytes.
The implementation can miss allocations if new thread is created and destroyed in between profiler snapshots.
diff -r 1898f77c754c -r 913c4e1341a6 jmh-core-it/src/test/java/org/openjdk/jmh/it/profilers/GCProfilerTest.java
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/jmh-core-it/src/test/java/org/openjdk/jmh/it/profilers/GCProfilerTest.java Sun Apr 12 16:34:47 2015 +0300
@@ -0,0 +1,63 @@
+package org.openjdk.jmh.it.profilers;
+
+import org.junit.Test;
+import org.openjdk.jmh.annotations.*;
+import org.openjdk.jmh.it.Fixtures;
+import org.openjdk.jmh.profile.GCProfiler;
+import org.openjdk.jmh.runner.Runner;
+import org.openjdk.jmh.runner.RunnerException;
+import org.openjdk.jmh.runner.options.Options;
+import org.openjdk.jmh.runner.options.OptionsBuilder;
+import org.openjdk.jmh.runner.options.TimeValue;
+
+import java.util.ArrayList;
+import java.util.concurrent.TimeUnit;
+
+/**
+ * Tests allocation profiler.
+ */
+ at OutputTimeUnit(TimeUnit.NANOSECONDS)
+public class GCProfilerTest {
+ @Benchmark
+ @Warmup(iterations = 2)
+ @Measurement(iterations = 1, time = 1, timeUnit = TimeUnit.MILLISECONDS)
+ @BenchmarkMode(Mode.AverageTime)
+ @Fork(1)
+ public Object allocateObject() {
+ return new Object();
+ }
+
+ @Benchmark
+ @Warmup(iterations = 2)
+ @Measurement(iterations = 5)
+ @BenchmarkMode(Mode.SingleShotTime)
+ @Fork(1)
+ public Object allocateObjectSingleShot() {
+ return new Object();
+ }
+
+ @Benchmark
+ @Warmup(iterations = 2)
+ @Measurement(iterations = 1)
+ @BenchmarkMode(Mode.SampleTime)
+ @Fork(1)
+ public Object allocateObjectSampleTime() {
+ return new Object();
+ }
+
+ @Test
+ public void testAllocationProfiler() throws RunnerException {
+ GCProfiler profiler = new GCProfiler();
+ ArrayList<String> errors = new ArrayList<String>();
+ if (!profiler.checkSupport(errors)) {
+ System.out.println("Allocation profiler is not available: " + errors.toString());
+ return;
+ }
+ Options opts = new OptionsBuilder()
+ .include(Fixtures.getTestMask(this.getClass()))
+ .addProfiler(GCProfiler.class)
+ .measurementTime(TimeValue.seconds(2))
+ .build();
+ new Runner(opts).run();
+ }
+}
diff -r 1898f77c754c -r 913c4e1341a6 jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java Tue Apr 07 13:13:18 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java Sun Apr 12 16:34:47 2015 +0300
@@ -56,6 +56,7 @@
private long beforeTime;
private long beforeGCCount;
private long beforeGCTime;
+ private HotspotAllocationSnapshot beforeAllocated;
private final NotificationListener listener;
private volatile Multiset<String> churn;
private Set<String> observedSpaces;
@@ -87,6 +88,7 @@
MemoryUsage after = entry.getValue();
MemoryUsage before = mapBefore.get(name);
long c = before.getUsed() - after.getUsed();
+ // Reporting code uses observedSpaces, so it reports 0 even if we omit adding
if (c > 0) {
churn.add(name, c);
observedSpaces.add(name);
@@ -138,6 +140,7 @@
}
this.beforeGCCount = gcCount;
this.beforeGCTime = gcTime;
+ this.beforeAllocated = HotspotAllocationSnapshot.create();
this.beforeTime = System.nanoTime();
}
@@ -146,6 +149,8 @@
uninstallHooks();
long afterTime = System.nanoTime();
+ HotspotAllocationSnapshot newSnapshot = HotspotAllocationSnapshot.create();
+
long gcTime = 0;
long gcCount = 0;
for (GarbageCollectorMXBean bean : ManagementFactory.getGarbageCollectorMXBeans()) {
@@ -155,6 +160,8 @@
List<ProfilerResult> results = new ArrayList<ProfilerResult>();
+ addAllocationResults(iResult, afterTime, newSnapshot, results);
+
results.add(new ProfilerResult(
Defaults.PREFIX + "gc.count",
gcCount - beforeGCCount,
@@ -168,16 +175,17 @@
AggregationPolicy.SUM));
for (String space : observedSpaces) {
- double churnRate = 1.0 * churn.count(space) * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime);
+ long churnBytes = churn.count(space);
results.add(new ProfilerResult(
Defaults.PREFIX + "gc.churn.{" + space + "}",
- churnRate / 1024 / 1024,
+ afterTime == beforeTime ? Double.NaN :
+ 1.0 * churnBytes * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime) / 1024 / 1024,
"MB/sec",
AggregationPolicy.AVG));
results.add(new ProfilerResult(Defaults.PREFIX + "gc.churn.{" + space + "}.norm",
- churnRate / iResult.getMetadata().getAllOps(),
+ churnBytes / iResult.getMetadata().getAllOps(),
"B/op",
AggregationPolicy.AVG));
}
@@ -185,6 +193,29 @@
return results;
}
+ private void addAllocationResults(IterationResult iResult, long afterTime, HotspotAllocationSnapshot newSnapshot, List<ProfilerResult> results) {
+ if (beforeAllocated == HotspotAllocationSnapshot.EMPTY) {
+ // When allocation profiling fails, make sure it is distinguishable in report
+ results.add(new ProfilerResult(Defaults.PREFIX + "gc.alloc.rate",
+ Double.NaN,
+ "MB/sec", AggregationPolicy.AVG));
+ return;
+ }
+ long allocated = newSnapshot.subtract(beforeAllocated);
+ // When no allocations measured, we still need to report results to avoid measurement bias.
+ results.add(
+ new ProfilerResult(Defaults.PREFIX + "gc.alloc.rate",
+ afterTime == beforeTime ? Double.NaN :
+ 1.0 * allocated / 1024 / 1024 * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime),
+ "MB/sec", AggregationPolicy.AVG));
+ long allOps = iResult.getMetadata().getAllOps();
+ results.add(
+ new ProfilerResult(Defaults.PREFIX + "gc.alloc.rate.norm",
+ allOps == 0 ? Double.NaN :
+ 1.0 * allocated / allOps,
+ "B/op", AggregationPolicy.AVG));
+ }
+
private boolean hooksInstalled;
public synchronized void installHooks() {
diff -r 1898f77c754c -r 913c4e1341a6 jmh-core/src/main/java/org/openjdk/jmh/profile/HotspotAllocationSnapshot.java
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/HotspotAllocationSnapshot.java Sun Apr 12 16:34:47 2015 +0300
@@ -0,0 +1,129 @@
+/*
+ * Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation. Oracle designates this
+ * particular file as subject to the "Classpath" exception as provided
+ * by Oracle in the LICENSE file that accompanied this code.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+package org.openjdk.jmh.profile;
+
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadMXBean;
+import java.lang.reflect.InvocationTargetException;
+import java.lang.reflect.Method;
+import java.util.HashMap;
+
+/**
+ * Records heap allocation snapshot and allows to estimate the allocations between two snapshots.
+ * The implementation is based on {@code ThreadMXBean.getThreadAllocatedBytes(long[])}.
+ */
+class HotspotAllocationSnapshot {
+ public final static HotspotAllocationSnapshot EMPTY = new HotspotAllocationSnapshot(new long[0], new long[0]);
+
+ // Volatiles are here for lazy initialization.
+ // Initialization in <clinit> was banned as having a "severe startup overhead"
+ private static volatile Method GET_THREAD_ALLOCATED_BYTES;
+ private static volatile boolean allocationNotAvailable;
+
+ private final long[] threadIds;
+ private final long[] allocatedBytes;
+
+ private HotspotAllocationSnapshot(long[] threadIds, long[] allocatedBytes) {
+ this.threadIds = threadIds;
+ this.allocatedBytes = allocatedBytes;
+ }
+
+ /**
+ * Takes a snapshot of thread allocation counters.
+ * The method might allocate, however it is assumed that allocations made by "current thread" will
+ * be excluded from the result while performing {@link HotspotAllocationSnapshot#subtract(HotspotAllocationSnapshot)}
+ *
+ * @return snapshot of thread allocation counters
+ */
+ public static HotspotAllocationSnapshot create() {
+ Method getBytes = getAllocatedBytesGetter();
+ if (getBytes == null) {
+ return HotspotAllocationSnapshot.EMPTY;
+ }
+ ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
+ try {
+ long[] threadIds = threadMXBean.getAllThreadIds();
+ long[] allocatedBytes = (long[]) getBytes.invoke(threadMXBean, (Object) threadIds);
+ return new HotspotAllocationSnapshot(threadIds, allocatedBytes);
+ } catch (IllegalAccessException e) {
+ // intentionally left blank
+ } catch (InvocationTargetException e) {
+ // intentionally left blank
+ }
+ // In exceptional cases, assume information is not available
+ return HotspotAllocationSnapshot.EMPTY;
+ }
+
+ /**
+ * Estimates allocated bytes based on two snapshots.
+ * The problem is threads can come and go while performing the benchmark,
+ * thus we would miss allocations made in a thread that was created and died between the snapshots.
+ * <p/>
+ * <p>Current thread is intentionally excluded since it believed to execute jmh infrastructure code only.
+ *
+ * @return estimated number of allocated bytes between profiler calls
+ */
+ public long subtract(HotspotAllocationSnapshot other) {
+ HashMap<Long, Integer> prevIndex = new HashMap<Long, Integer>();
+ for (int i = 0; i < other.threadIds.length; i++) {
+ long id = other.threadIds[i];
+ prevIndex.put(id, i);
+ }
+ long currentThreadId = Thread.currentThread().getId();
+ long allocated = 0;
+ for (int i = 0; i < threadIds.length; i++) {
+ long id = threadIds[i];
+ if (id == currentThreadId) {
+ continue;
+ }
+ allocated += allocatedBytes[i];
+ Integer prev = prevIndex.get(id);
+ if (prev != null) {
+ allocated -= other.allocatedBytes[prev];
+ }
+ }
+ return allocated;
+ }
+
+ private static Method getAllocatedBytesGetter() {
+ Method getBytes = GET_THREAD_ALLOCATED_BYTES;
+ if (getBytes != null || allocationNotAvailable) {
+ return getBytes;
+ }
+ // We do not care to execute reflection code multiple times if it fails
+ // User should not call
+ ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
+ try {
+ getBytes = threadMXBean.getClass().getMethod("getThreadAllocatedBytes", long[].class);
+ getBytes.setAccessible(true);
+ } catch (Throwable e) { // To avoid jmh failure in case of incompatible JDK and/or inaccessible method
+ getBytes = null;
+ allocationNotAvailable = true;
+ System.out.println("Allocation profiling is not available: " + e.getMessage());
+ }
+ GET_THREAD_ALLOCATED_BYTES = getBytes;
+ return getBytes;
+ }
+}
diff -r 1898f77c754c -r 913c4e1341a6 jmh-core/src/main/java/org/openjdk/jmh/profile/Profiler.java
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/Profiler.java Tue Apr 07 13:13:18 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/Profiler.java Sun Apr 12 16:34:47 2015 +0300
@@ -38,7 +38,7 @@
/**
* Check the support for a given profiler.
* @param msgs where to put the diagnostic messages
- * @return true, if suppported
+ * @return true, if supported
*/
boolean checkSupport(List<String> msgs);
More information about the jmh-dev
mailing list