changeset 1198:1c90c38e04d5

7901386: Allocation rate profiler Summary: -prof gc now also reports allocation rates. Contributed-by: Vladimir Sitnikov <sitnikov.vladimir@gmail.com>
author shade
date Thu, 16 Apr 2015 01:22:51 +0300
parents 03adf23f98ed
children 9941b60412bd
files jmh-core-it/src/test/java/org/openjdk/jmh/it/profilers/GCProfilerTest.java jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java jmh-core/src/main/java/org/openjdk/jmh/profile/Profiler.java
diffstat 3 files changed, 224 insertions(+), 4 deletions(-) [+]
line wrap: on
line diff
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/jmh-core-it/src/test/java/org/openjdk/jmh/it/profilers/GCProfilerTest.java	Thu Apr 16 01:22:51 2015 +0300
@@ -0,0 +1,94 @@
+/*
+ * 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.it.profilers;
+
+import org.junit.Test;
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.BenchmarkMode;
+import org.openjdk.jmh.annotations.Fork;
+import org.openjdk.jmh.annotations.Measurement;
+import org.openjdk.jmh.annotations.Mode;
+import org.openjdk.jmh.annotations.OutputTimeUnit;
+import org.openjdk.jmh.annotations.Warmup;
+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.
+ */
+@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();
+    }
+}
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java	Wed Apr 15 22:04:59 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java	Thu Apr 16 01:22:51 2015 +0300
@@ -40,12 +40,14 @@
 import java.lang.management.GarbageCollectorMXBean;
 import java.lang.management.ManagementFactory;
 import java.lang.management.MemoryUsage;
+import java.lang.management.ThreadMXBean;
 import java.lang.reflect.Field;
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.Collections;
+import java.util.HashMap;
 import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
@@ -56,6 +58,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 +90,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 +142,7 @@
         }
         this.beforeGCCount = gcCount;
         this.beforeGCTime = gcTime;
+        this.beforeAllocated = HotspotAllocationSnapshot.create();
         this.beforeTime = System.nanoTime();
     }
 
@@ -146,6 +151,8 @@
         uninstallHooks();
         long afterTime = System.nanoTime();
 
+        HotspotAllocationSnapshot newSnapshot = HotspotAllocationSnapshot.create();
+
         long gcTime = 0;
         long gcCount = 0;
         for (GarbageCollectorMXBean bean : ManagementFactory.getGarbageCollectorMXBeans()) {
@@ -155,6 +162,27 @@
 
         List<ProfilerResult> results = new ArrayList<ProfilerResult>();
 
+        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));
+        } else {
+            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) ?
+                                    1.0 * allocated / 1024 / 1024 * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime) :
+                                    Double.NaN,
+                            "MB/sec", AggregationPolicy.AVG));
+            long allOps = iResult.getMetadata().getAllOps();
+            results.add(new ProfilerResult(Defaults.PREFIX + "gc.alloc.rate.norm",
+                            (allOps != 0) ?
+                                    1.0 * allocated / allOps :
+                                    Double.NaN,
+                            "B/op", AggregationPolicy.AVG));
+        }
+
         results.add(new ProfilerResult(
                 Defaults.PREFIX + "gc.count",
                 gcCount - beforeGCCount,
@@ -168,17 +196,22 @@
                 AggregationPolicy.SUM));
 
         for (String space : observedSpaces) {
-            double churnRate = 1.0 * churn.count(space) * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime);
+            double churnRate = (afterTime != beforeTime) ?
+                    1.0 * churn.count(space) * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime) / 1024 / 1024 :
+                    Double.NaN;
+
+            double churnNorm = 1.0 * churn.count(space) / iResult.getMetadata().getAllOps();
+
             String spaceName = space.replaceAll(" ", "_");
 
             results.add(new ProfilerResult(
                     Defaults.PREFIX + "gc.churn." + spaceName + "",
-                    churnRate / 1024 / 1024,
+                    churnRate,
                     "MB/sec",
                     AggregationPolicy.AVG));
 
             results.add(new ProfilerResult(Defaults.PREFIX + "gc.churn." + spaceName + ".norm",
-                    churnRate / iResult.getMetadata().getAllOps(),
+                    churnNorm,
                     "B/op",
                     AggregationPolicy.AVG));
         }
@@ -211,4 +244,97 @@
         }
     }
 
+    static 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
+            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;
+        }
+    }
+
 }
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/Profiler.java	Wed Apr 15 22:04:59 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/Profiler.java	Thu Apr 16 01:22:51 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);