changeset 172:4fc586852aff

Prune the human-readable output, fix the long-standing usability glitches.
author shade
date Fri, 30 Aug 2013 20:36:02 +0400
parents 22d270744285
children f762f75d97c4
files jmh-core/src/main/java/org/openjdk/jmh/logic/results/AverageTimePerOp.java jmh-core/src/main/java/org/openjdk/jmh/logic/results/OpsPerTimeUnit.java jmh-core/src/main/java/org/openjdk/jmh/logic/results/Result.java jmh-core/src/main/java/org/openjdk/jmh/logic/results/SampleTimePerOp.java jmh-core/src/main/java/org/openjdk/jmh/logic/results/SingleShotTime.java jmh-core/src/main/java/org/openjdk/jmh/output/format/PrettyPrintFormat.java jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java jmh-core/src/main/java/org/openjdk/jmh/runner/parameters/TimeValue.java jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestAverageTimePerOp.java jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestOpsPerTimeUnit.java jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestSampleTimePerOp.java jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestSingleShotTime.java
diffstat 12 files changed, 69 insertions(+), 88 deletions(-) [+]
line wrap: on
line diff
--- a/jmh-core/src/main/java/org/openjdk/jmh/logic/results/AverageTimePerOp.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/logic/results/AverageTimePerOp.java	Fri Aug 30 20:36:02 2013 +0400
@@ -24,6 +24,7 @@
  */
 package org.openjdk.jmh.logic.results;
 
+import org.openjdk.jmh.runner.parameters.TimeValue;
 import org.openjdk.jmh.util.internal.Statistics;
 
 import java.util.Collection;
@@ -64,7 +65,7 @@
     /** {@inheritDoc} */
     @Override
     public String getScoreUnit() {
-        return tuToString(outputTimeUnit) + "/op";
+        return TimeValue.tuToString(outputTimeUnit) + "/op";
     }
 
     /** {@inheritDoc} */
--- a/jmh-core/src/main/java/org/openjdk/jmh/logic/results/OpsPerTimeUnit.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/logic/results/OpsPerTimeUnit.java	Fri Aug 30 20:36:02 2013 +0400
@@ -24,6 +24,7 @@
  */
 package org.openjdk.jmh.logic.results;
 
+import org.openjdk.jmh.runner.parameters.TimeValue;
 import org.openjdk.jmh.util.internal.Statistics;
 
 import java.util.Collection;
@@ -74,7 +75,7 @@
     /** {@inheritDoc} */
     @Override
     public String getScoreUnit() {
-        return "ops/" + tuToString(outputTimeUnit);
+        return "ops/" + TimeValue.tuToString(outputTimeUnit);
     }
 
     /** {@inheritDoc} */
--- a/jmh-core/src/main/java/org/openjdk/jmh/logic/results/Result.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/logic/results/Result.java	Fri Aug 30 20:36:02 2013 +0400
@@ -93,15 +93,13 @@
         if (statistics.getN() > 2) {
             double[] interval95 = statistics.getConfidenceInterval(0.05);
             double[] interval99 = statistics.getConfidenceInterval(0.01);
-            pw.println(String.format("Run result \"%s\": %.3f \u00B1(95%%) %.3f \u00B1(99%%) %.3f %s",
-                    label,
+            pw.println(String.format("Result%s: %.3f \u00B1(95%%) %.3f \u00B1(99%%) %.3f %s",
+                    (label == null) ? "" : "\"" + label + "\"",
                     (interval95[0] + interval95[1]) / 2, (interval95[1] - interval95[0]) / 2, (interval99[1] - interval99[0]) / 2,
                     getScoreUnit()));
-            pw.println(String.format("Run statistics \"%s\": min = %.3f, avg = %.3f, max = %.3f, stdev = %.3f",
-                    label,
+            pw.println(String.format("  Statistics: (min, avg, max) = (%.3f, %.3f, %.3f), stdev = %.3f",
                     statistics.getMin(), statistics.getMean(), statistics.getMax(), statistics.getStandardDeviation()));
-            pw.println(String.format("Run confidence intervals \"%s\": 95%% [%.3f, %.3f], 99%% [%.3f, %.3f]",
-                    label,
+            pw.println(String.format("  Confidence intervals: 95%% [%.3f, %.3f], 99%% [%.3f, %.3f]",
                     interval95[0], interval95[1], interval99[0], interval99[1]));
         } else {
             pw.println(String.format("Run result: %.2f (<= 2 iterations)", statistics.getMean()));
@@ -110,32 +108,6 @@
         return sw.toString();
     }
 
-    /**
-     * Converts timeunit to stringly representation.
-     *
-     * @param timeUnit timeunit to convert
-     * @return string representation
-     */
-    public static String tuToString(TimeUnit timeUnit) {
-        switch (timeUnit) {
-            case DAYS:
-                return "day";
-            case HOURS:
-                return "hour";
-            case MICROSECONDS:
-                return "usec";
-            case MILLISECONDS:
-                return "msec";
-            case MINUTES:
-                return "min";
-            case NANOSECONDS:
-                return "nsec";
-            case SECONDS:
-                return "sec";
-            default:
-                return "?";
-        }
-    }
 
 
     public String getLabel() {
--- a/jmh-core/src/main/java/org/openjdk/jmh/logic/results/SampleTimePerOp.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/logic/results/SampleTimePerOp.java	Fri Aug 30 20:36:02 2013 +0400
@@ -24,6 +24,7 @@
  */
 package org.openjdk.jmh.logic.results;
 
+import org.openjdk.jmh.runner.parameters.TimeValue;
 import org.openjdk.jmh.util.internal.BootstrappedStatistics;
 import org.openjdk.jmh.util.internal.SampleBuffer;
 import org.openjdk.jmh.util.internal.Statistics;
@@ -62,7 +63,7 @@
     /** {@inheritDoc} */
     @Override
     public String getScoreUnit() {
-        return tuToString(outputTimeUnit) + "/op";
+        return TimeValue.tuToString(outputTimeUnit) + "/op";
     }
 
     /** {@inheritDoc} */
--- a/jmh-core/src/main/java/org/openjdk/jmh/logic/results/SingleShotTime.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/logic/results/SingleShotTime.java	Fri Aug 30 20:36:02 2013 +0400
@@ -24,6 +24,7 @@
  */
 package org.openjdk.jmh.logic.results;
 
+import org.openjdk.jmh.runner.parameters.TimeValue;
 import org.openjdk.jmh.util.internal.Statistics;
 
 import java.util.Collection;
@@ -60,7 +61,7 @@
     /** {@inheritDoc} */
     @Override
     public String getScoreUnit() {
-        return tuToString(outputTimeUnit)+"s";
+        return TimeValue.tuToString(outputTimeUnit);
     }
 
     /** {@inheritDoc} */
--- a/jmh-core/src/main/java/org/openjdk/jmh/output/format/PrettyPrintFormat.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/output/format/PrettyPrintFormat.java	Fri Aug 30 20:36:02 2013 +0400
@@ -56,8 +56,7 @@
         sb.append(data.getPrimaryResult().toString());
 
         if (type == IterationType.MEASUREMENT) {
-            int prefixLen = String.format("Iteration %3d (%s in %d %s): ", iteration,
-                    params.getTime(), params.getThreads(), getThreadsString(params.getThreads())).length();
+            int prefixLen = String.format("Iteration %3d: ", iteration).length();
 
             Map<String, Result> secondary = data.getSecondaryResults();
             if (!secondary.isEmpty()) {
@@ -107,14 +106,9 @@
             out.println("# Starting run at: " + new Date());
         }
 
-        out.println("# Runtime (per iteration): " + mbParams.getIteration().getTime());
-        out.println("# Iterations: " + mbParams.getIteration().getCount());
-        out.println("# Thread count: " + mbParams.getThreads());
-
-        if (mbParams.shouldSynchIterations()) {
-            out.println("# Threads will synchronize iterations");
-        }
-
+        out.println("# Warmup: " + mbParams.getWarmup().getCount() + " iterations, " + mbParams.getWarmup().getTime() + " each");
+        out.println("# Measurement: " + mbParams.getIteration().getCount() + " iterations, " + mbParams.getIteration().getTime() + " each");
+        out.println("# Threads: " + mbParams.getThreads() + " " + getThreadsString(mbParams.getThreads()) + (mbParams.shouldSynchIterations() ? ", will synchronize iterations" : ""));
         out.println("# Benchmark mode: " + name.getMode().longLabel());
         out.println("# Running: " + name.getUsername());
     }
@@ -126,7 +120,7 @@
         benchmarkResults.put(name, result);
 
         out.println();
-        out.println(result.getPrimaryResult().extendedInfo("***"));
+        out.println(result.getPrimaryResult().extendedInfo(null));
         for (Result r : result.getSecondaryResults().values()) {
             out.println(r.extendedInfo(r.getLabel()));
         }
@@ -144,10 +138,11 @@
             Collection<RunResult> forkedResults = benchmarkResults.get(key);
             if (forkedResults.size() > 1) {
                 out.println("\"" + key.getUsername() + "\", aggregate over forked runs:");
+                out.println();
 
                 RunResult runResult = RunResult.merge(forkedResults);
 
-                out.println(runResult.getPrimaryResult().extendedInfo("***"));
+                out.println(runResult.getPrimaryResult().extendedInfo(null));
                 for (Result r : runResult.getSecondaryResults().values()) {
                     out.println(r.extendedInfo(r.getLabel()));
                 }
@@ -159,12 +154,10 @@
     public void iteration(BenchmarkRecord benchmark, IterationParams params, int iteration, IterationType type) {
         switch (type) {
             case WARMUP:
-                out.print(String.format("# Warmup Iteration %3d (%s in %d %s): ", iteration,
-                        params.getTime(), params.getThreads(), getThreadsString(params.getThreads())));
+                out.print(String.format("# Warmup Iteration %3d: ", iteration));
                 break;
             case MEASUREMENT:
-                out.print(String.format("Iteration %3d (%s in %d %s): ", iteration,
-                        params.getTime(), params.getThreads(), getThreadsString(params.getThreads())));
+                out.print(String.format("Iteration %3d: ", iteration));
                 break;
             default:
                 throw new IllegalStateException("Unknown iteration type: " + type);
--- a/jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java	Fri Aug 30 20:36:02 2013 +0400
@@ -214,14 +214,18 @@
             // increased variance.
             // currently valid only for non-external JVM runs
 
+            int count = 0;
             for (BenchmarkRecord benchmark : warmupMicros) {
+                out.println("# Fork: N/A, bulk warmup in progress, " + (++count) + " of " + warmupMicros.size());
                 runBenchmark(benchmark, true, false);
+                out.println("");
             }
         }
         // run microbenchmarks
         //
         Map<BenchmarkRecord, RunResult> results = new TreeMap<BenchmarkRecord, RunResult>();
         for (BenchmarkRecord benchmark : benchmarks) {
+            out.println("# Fork: N/A, test runs in same VM");
             RunResult result = runBenchmark(benchmark, false, true);
             results.put(benchmark, RunResult.merge(results.get(benchmark), result));
         }
@@ -266,6 +270,7 @@
 
         Map<BenchmarkRecord, RunResult> results = new TreeMap<BenchmarkRecord, RunResult>();
         for (BenchmarkRecord benchmark : embedded) {
+            out.println("# Fork: N/A, test runs in same VM");
             RunResult r = runBenchmark(benchmark, true, true);
             results.put(benchmark, RunResult.merge(results.get(benchmark), r));
         }
@@ -343,13 +348,14 @@
             String[] warmupForkCheat = Utils.concat(commandString, new String[]{"-wi", "1", "-i", "0"});
             out.verbosePrintln("Warmup forking " + warmupForkCount + " times using command: " + Arrays.toString(warmupForkCheat));
             for (int i = 0; i < warmupForkCount; i++) {
+                out.println("# Warmup Fork: " + (i+1) + " of " + forkCount);
                 doFork(reader, warmupForkCheat);
             }
         }
 
-        // TODO: should we report fork number somehow?
         out.verbosePrintln("Forking " + forkCount + " times using command: " + Arrays.toString(commandString));
         for (int i = 0; i < forkCount; i++) {
+            out.println("# Fork: " + (i+1) + " of " + forkCount);
             doFork(reader, commandString);
         }
     }
--- a/jmh-core/src/main/java/org/openjdk/jmh/runner/parameters/TimeValue.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/runner/parameters/TimeValue.java	Fri Aug 30 20:36:02 2013 +0400
@@ -113,28 +113,34 @@
         if (time == 0) {
             return "single-shot";
         } else {
-            return String.valueOf(time) + timeUnitString();
+            return String.valueOf(time) + " " + tuToString(timeUnit);
         }
     }
 
-    public String toCommandLine() {
-        return String.valueOf(time) + timeUnitString();
-    }
-
-    private String timeUnitString() {
-        switch(timeUnit) {
+    /**
+     * Converts timeunit to stringly representation.
+     *
+     * @param timeUnit timeunit to convert
+     * @return string representation
+     */
+    public static String tuToString(TimeUnit timeUnit) {
+        switch (timeUnit) {
+            case DAYS:
+                return "day";
+            case HOURS:
+                return "hr";
+            case MICROSECONDS:
+                return "us";
+            case MILLISECONDS:
+                return "ms";
+            case MINUTES:
+                return "min";
+            case NANOSECONDS:
+                return "ns";
             case SECONDS:
                 return "s";
-            case MILLISECONDS:
-                return "ms";
-            case MICROSECONDS:
-                return "us";
-            case NANOSECONDS:
-                return "ns";
-            case MINUTES:
-                return "m";
             default:
-                return "s";
+                return "?";
         }
     }
 
--- a/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestAverageTimePerOp.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestAverageTimePerOp.java	Fri Aug 30 20:36:02 2013 +0400
@@ -44,7 +44,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(1.5, result.getScore());
-        assertEquals("usec/op", result.getScoreUnit());
+        assertEquals("us/op", result.getScoreUnit());
     }
 
     @Test
@@ -54,7 +54,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(1.0, result.getScore());
-        assertEquals("usec/op", result.getScoreUnit());
+        assertEquals("us/op", result.getScoreUnit());
     }
 
     @Test
@@ -64,7 +64,7 @@
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(1.0, result.getScore());
-        assertEquals("usec/op", result.getScoreUnit());
+        assertEquals("us/op", result.getScoreUnit());
     }
 
     @Test
@@ -74,6 +74,6 @@
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(1.5, result.getScore());
-        assertEquals("usec/op", result.getScoreUnit());
+        assertEquals("us/op", result.getScoreUnit());
     }
 }
--- a/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestOpsPerTimeUnit.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestOpsPerTimeUnit.java	Fri Aug 30 20:36:02 2013 +0400
@@ -58,7 +58,7 @@
 
         OpsPerTimeUnit instanceh = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 1000L, 1000000L, TimeUnit.HOURS);
         assertEquals(3600000000.0000005D, instanceh.getScore(), 0.0);
-        assertEquals("ops/hour", instanceh.getScoreUnit());
+        assertEquals("ops/hr", instanceh.getScoreUnit());
 
         OpsPerTimeUnit instancem = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 1000L, 1000000L, TimeUnit.MINUTES);
         assertEquals(60000000, instancem.getScore(), 0.0);
@@ -66,19 +66,19 @@
 
         OpsPerTimeUnit instance = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 1000L, 1000000L, TimeUnit.SECONDS);
         assertEquals(1000000, instance.getScore(), 0.0);
-        assertEquals("ops/sec", instance.getScoreUnit());
+        assertEquals("ops/s", instance.getScoreUnit());
 
         OpsPerTimeUnit instance2 = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 1000L, 1000000L, TimeUnit.MILLISECONDS);
         assertEquals(1000, instance2.getScore(), 0.0);
-        assertEquals("ops/msec", instance2.getScoreUnit());
+        assertEquals("ops/ms", instance2.getScoreUnit());
 
         OpsPerTimeUnit instance3 = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 1000L, 1000000L, TimeUnit.MICROSECONDS);
         assertEquals(1, instance3.getScore(), 0.0);
-        assertEquals("ops/usec", instance3.getScoreUnit());
+        assertEquals("ops/us", instance3.getScoreUnit());
 
         OpsPerTimeUnit instance4 = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 1000L, 1000000L, TimeUnit.NANOSECONDS);
         assertEquals(0.001, instance4.getScore(), 0.0);
-        assertEquals("ops/nsec", instance4.getScoreUnit());
+        assertEquals("ops/ns", instance4.getScoreUnit());
     }
 
     @Test
@@ -88,7 +88,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(150.0, result.getScore());
-        assertEquals("ops/msec", result.getScoreUnit());
+        assertEquals("ops/ms", result.getScoreUnit());
     }
 
     @Test
@@ -98,7 +98,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(100.0, result.getScore());
-        assertEquals("ops/msec", result.getScoreUnit());
+        assertEquals("ops/ms", result.getScoreUnit());
     }
 
     @Test // regression test, check for overflow
@@ -108,7 +108,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(100000000.0, result.getScore());
-        assertEquals("ops/msec", result.getScoreUnit());
+        assertEquals("ops/ms", result.getScoreUnit());
     }
 
     @Test
@@ -117,7 +117,7 @@
         OpsPerTimeUnit r2 = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 2000L, 10000000L, TimeUnit.MILLISECONDS);
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
-        assertEquals("ops/msec", result.getScoreUnit());
+        assertEquals("ops/ms", result.getScoreUnit());
         assertEquals(300.0, result.getScore());
     }
 
@@ -127,7 +127,7 @@
         OpsPerTimeUnit r2 = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 2000L, 20000000L, TimeUnit.MILLISECONDS);
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
-        assertEquals("ops/msec", result.getScoreUnit());
+        assertEquals("ops/ms", result.getScoreUnit());
         assertEquals(200.0, result.getScore());
     }
 
@@ -137,7 +137,7 @@
         OpsPerTimeUnit r2 = new OpsPerTimeUnit(ResultRole.BOTH, "test1", 2000000000L, 20000000L, TimeUnit.MILLISECONDS);
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
-        assertEquals("ops/msec", result.getScoreUnit());
+        assertEquals("ops/ms", result.getScoreUnit());
         assertEquals(200000000.0, result.getScore());
     }
 }
--- a/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestSampleTimePerOp.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestSampleTimePerOp.java	Fri Aug 30 20:36:02 2013 +0400
@@ -53,7 +53,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(2.5, result.getScore());
-        assertEquals("usec/op", result.getScoreUnit());
+        assertEquals("us/op", result.getScoreUnit());
     }
 
     @Test
@@ -71,7 +71,7 @@
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(2.5, result.getScore());
-        assertEquals("usec/op", result.getScoreUnit());
+        assertEquals("us/op", result.getScoreUnit());
     }
 
 }
--- a/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestSingleShotTime.java	Fri Aug 30 12:38:04 2013 +0400
+++ b/jmh-core/src/test/java/org/openjdk/jmh/logic/results/TestSingleShotTime.java	Fri Aug 30 20:36:02 2013 +0400
@@ -44,7 +44,7 @@
         Result result = r1.getRunAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(1.5, result.getScore());
-        assertEquals("usecs", result.getScoreUnit());
+        assertEquals("us", result.getScoreUnit());
     }
 
     @Test
@@ -54,7 +54,7 @@
         Result result = r1.getIterationAggregator().aggregate(Arrays.asList(r1, r2));
 
         assertEquals(1.5, result.getScore());
-        assertEquals("usecs", result.getScoreUnit());
+        assertEquals("us", result.getScoreUnit());
     }
 
 }