changeset 1209:172094a4b2c4

7901402: Unbias secondary results in BenchmarkResult Contributed-by: Vladimir Sitnikov <sitnikov.vladimir@gmail.com>
author shade
date Thu, 23 Apr 2015 14:40:38 +0300
parents eedfa64aa9da
children 61f8242ff23c
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/ProfilerResult.java jmh-core/src/main/java/org/openjdk/jmh/results/BenchmarkResult.java jmh-core/src/main/java/org/openjdk/jmh/results/Result.java
diffstat 5 files changed, 74 insertions(+), 55 deletions(-) [+]
line wrap: on
line diff
--- a/jmh-core-it/src/test/java/org/openjdk/jmh/it/profilers/GCProfilerTest.java	Thu Apr 23 01:56:42 2015 +0300
+++ b/jmh-core-it/src/test/java/org/openjdk/jmh/it/profilers/GCProfilerTest.java	Thu Apr 23 14:40:38 2015 +0300
@@ -25,20 +25,13 @@
 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.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;
@@ -47,13 +40,21 @@
  * Tests allocation profiler.
  */
 @OutputTimeUnit(TimeUnit.NANOSECONDS)
+@Fork(1) // 0 to enable debugging
 public class GCProfilerTest {
 
     @Benchmark
+    @Warmup(iterations = 0)
+    @Measurement(iterations = 20, time = 10, timeUnit = TimeUnit.MILLISECONDS)
+    @BenchmarkMode(Mode.AverageTime)
+    public Object allocateObjectNoWarmup() {
+        return new Object();
+    }
+
+    @Benchmark
     @Warmup(iterations = 2)
-    @Measurement(iterations = 1, time = 1, timeUnit = TimeUnit.MILLISECONDS)
+    @Measurement(iterations = 2, time = 2, timeUnit = TimeUnit.SECONDS)
     @BenchmarkMode(Mode.AverageTime)
-    @Fork(1)
     public Object allocateObject() {
         return new Object();
     }
@@ -62,16 +63,14 @@
     @Warmup(iterations = 2)
     @Measurement(iterations = 5)
     @BenchmarkMode(Mode.SingleShotTime)
-    @Fork(1)
     public Object allocateObjectSingleShot() {
         return new Object();
     }
 
     @Benchmark
     @Warmup(iterations = 2)
-    @Measurement(iterations = 1)
+    @Measurement(iterations = 1, time = 2, timeUnit = TimeUnit.SECONDS)
     @BenchmarkMode(Mode.SampleTime)
-    @Fork(1)
     public Object allocateObjectSampleTime() {
         return new Object();
     }
@@ -87,7 +86,6 @@
         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	Thu Apr 23 01:56:42 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/GCProfiler.java	Thu Apr 23 14:40:38 2015 +0300
@@ -44,14 +44,7 @@
 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;
-import java.util.Set;
+import java.util.*;
 import java.util.concurrent.TimeUnit;
 
 public class GCProfiler implements InternalProfiler {
@@ -61,11 +54,9 @@
     private HotspotAllocationSnapshot beforeAllocated;
     private final NotificationListener listener;
     private volatile Multiset<String> churn;
-    private Set<String> observedSpaces;
 
     public GCProfiler() {
         churn = new HashMultiset<String>();
-        observedSpaces = Collections.synchronizedSet(new HashSet<String>());
 
         NotificationListener listener = null;
         try {
@@ -90,10 +81,8 @@
                                 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);
                                 }
                             }
                         }
@@ -169,18 +158,20 @@
                     "MB/sec", AggregationPolicy.AVG));
         } else {
             long allocated = newSnapshot.subtract(beforeAllocated);
-            // When no allocations measured, we still need to report results to avoid measurement bias.
+            // When no allocations measured, we still need to report results to avoid user confusion
             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));
+            if (allocated != 0) {
+                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(
@@ -189,13 +180,15 @@
                 "counts",
                 AggregationPolicy.SUM));
 
-        results.add(new ProfilerResult(
-                Defaults.PREFIX + "gc.time",
-                gcTime - beforeGCTime,
-                "ms",
-                AggregationPolicy.SUM));
+        if (gcCount != beforeGCCount || gcTime != beforeGCTime) {
+            results.add(new ProfilerResult(
+                    Defaults.PREFIX + "gc.time",
+                    gcTime - beforeGCTime,
+                    "ms",
+                    AggregationPolicy.SUM));
+        }
 
-        for (String space : observedSpaces) {
+        for (String space : churn.keys()) {
             double churnRate = (afterTime != beforeTime) ?
                     1.0 * churn.count(space) * TimeUnit.SECONDS.toNanos(1) / (afterTime - beforeTime) / 1024 / 1024 :
                     Double.NaN;
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/ProfilerResult.java	Thu Apr 23 01:56:42 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/ProfilerResult.java	Thu Apr 23 14:40:38 2015 +0300
@@ -51,4 +51,8 @@
         return new ProfilerResultAggregator();
     }
 
+    @Override
+    protected ProfilerResult getZeroResult() {
+        return new ProfilerResult(label, 0, unit, policy);
+    }
 }
--- a/jmh-core/src/main/java/org/openjdk/jmh/results/BenchmarkResult.java	Thu Apr 23 01:56:42 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/results/BenchmarkResult.java	Thu Apr 23 14:40:38 2015 +0300
@@ -31,9 +31,7 @@
 import java.io.Serializable;
 import java.util.ArrayList;
 import java.util.Collection;
-import java.util.HashSet;
 import java.util.Map;
-import java.util.Set;
 import java.util.TreeMap;
 
 /**
@@ -101,26 +99,43 @@
     }
 
     public Map<String, Result> getSecondaryResults() {
-        Set<String> labels = new HashSet<String>();
-        for (IterationResult r : iterationResults) {
-            labels.addAll(r.getSecondaryResults().keySet());
+        // label -> collection of results
+        Multimap<String, Result> allSecondary = new HashMultimap<String, Result>();
+
+        // Build multiset of all results to capture if some labels are missing in some of the iterations
+        for (IterationResult ir : iterationResults) {
+            Map<String, Result> secondaryResults = ir.getSecondaryResults();
+            for (Map.Entry<String, Result> entry : secondaryResults.entrySet()) {
+                allSecondary.put(entry.getKey(), entry.getValue());
+            }
         }
 
         Map<String, Result> answers = new TreeMap<String, Result>();
-        for (String label : labels) {
-            Aggregator<Result> aggregator = null;
-            Collection<Result> results = new ArrayList<Result>();
-            for (IterationResult r : iterationResults) {
-                Result e = r.getSecondaryResults().get(label);
-                if (e != null) {
-                    results.add(e);
-                    aggregator = e.getIterationAggregator();
+
+        int totalIterations = iterationResults.size();
+        // Create "0" entries in case certain labels did not appear in some of the iterations
+        for (String label : allSecondary.keys()) {
+            Collection<Result> results = allSecondary.get(label);
+            Result firstResult = results.iterator().next();
+            Result emptyResult = firstResult.getZeroResult();
+            if (emptyResult != null) {
+                for (int i = results.size(); i < totalIterations; i++) {
+                    allSecondary.put(label, emptyResult);
                 }
             }
+            @SuppressWarnings("unchecked")
+            Aggregator<Result> aggregator = firstResult.getIterationAggregator();
+            if (aggregator == null) {
+                if (results.size() == 1) {
+                    answers.put(label, firstResult);
+                    continue;
+                }
+                throw new IllegalStateException("No aggregator for " + firstResult);
+            }
 
-            if (aggregator != null) {
-                answers.put(label, aggregator.aggregate(results));
-            }
+            // Note: should not use "results" here since the contents was just updated by "put" above
+            Result aggregate = aggregator.aggregate(allSecondary.get(label));
+            answers.put(label, aggregate);
         }
 
         for (String label : benchmarkResults.keys()) {
--- a/jmh-core/src/main/java/org/openjdk/jmh/results/Result.java	Thu Apr 23 01:56:42 2015 +0300
+++ b/jmh-core/src/main/java/org/openjdk/jmh/results/Result.java	Thu Apr 23 14:40:38 2015 +0300
@@ -171,6 +171,15 @@
     protected abstract Aggregator<T> getIterationAggregator();
 
     /**
+     * Returns "0" result. This is used for un-biased aggregation of secondary results.
+     * For instance, profilers might omit results in some iterations, thus we should pretend there were 0 results.
+     * @return result that represents "empty" result, null if no sensible "empty" result can be created
+     */
+    protected T getZeroResult() {
+        return null;
+    }
+
+    /**
      * Result as represented by a String.
      *
      * @return String with the result and unit