changeset 1422:daa249176624

7901966: Profilers mishandle filtering when VM startup is slow
author shade
date Tue, 02 May 2017 20:11:37 +0200
parents 2e4ec571fd74
children 2e3213e9e8d4
files jmh-core/src/main/java/org/openjdk/jmh/profile/AbstractPerfAsmProfiler.java jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfNormProfiler.java jmh-core/src/main/java/org/openjdk/jmh/profile/ProfilerUtils.java jmh-core/src/main/java/org/openjdk/jmh/profile/SafepointsProfiler.java jmh-core/src/main/java/org/openjdk/jmh/results/BenchmarkResultMetaData.java jmh-core/src/main/java/org/openjdk/jmh/runner/BaseRunner.java jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java
diffstat 7 files changed, 36 insertions(+), 11 deletions(-) [+]
line wrap: on
line diff
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/AbstractPerfAsmProfiler.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/AbstractPerfAsmProfiler.java	Tue May 02 20:11:37 2017 +0200
@@ -344,7 +344,7 @@
 
         long skipMs;
         if (delayMsec == -1) { // not set
-            skipMs = ProfilerUtils.warmupDelayMs(br);
+            skipMs = ProfilerUtils.measurementDelayMs(br);
         } else {
             skipMs = delayMsec;
         }
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfNormProfiler.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfNormProfiler.java	Tue May 02 20:11:37 2017 +0200
@@ -39,7 +39,6 @@
 import java.text.NumberFormat;
 import java.text.ParseException;
 import java.util.*;
-import java.util.concurrent.TimeUnit;
 
 public class LinuxPerfNormProfiler implements ExternalProfiler {
 
@@ -188,7 +187,7 @@
 
             long skipMs;
             if (delayMs == -1) { // not set
-                skipMs = ProfilerUtils.warmupDelayMs(br);
+                skipMs = ProfilerUtils.measurementDelayMs(br);
             } else {
                 skipMs = delayMs;
             }
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/ProfilerUtils.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/ProfilerUtils.java	Tue May 02 20:11:37 2017 +0200
@@ -82,7 +82,7 @@
         return set;
     }
 
-    public static long warmupDelayMs(BenchmarkResult br) {
+    public static long measurementDelayMs(BenchmarkResult br) {
         BenchmarkResultMetaData md = br.getMetadata();
         if (md != null) {
             // try to ask harness itself:
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/SafepointsProfiler.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/SafepointsProfiler.java	Tue May 02 20:11:37 2017 +0200
@@ -76,7 +76,7 @@
         long measuredTimeMs = ProfilerUtils.measuredTimeMs(br);
         long measuredTimeNs = TimeUnit.MILLISECONDS.toNanos(measuredTimeMs);
 
-        long measureFrom = TimeUnit.MILLISECONDS.toNanos(ProfilerUtils.warmupDelayMs(br));
+        long measureFrom = TimeUnit.MILLISECONDS.toNanos(ProfilerUtils.measurementDelayMs(br));
         long measureTo = measureFrom + measuredTimeNs;
 
         List<ParsedData> ds = new ArrayList<>();
--- a/jmh-core/src/main/java/org/openjdk/jmh/results/BenchmarkResultMetaData.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/results/BenchmarkResultMetaData.java	Tue May 02 20:11:37 2017 +0200
@@ -28,14 +28,16 @@
 
 public class BenchmarkResultMetaData implements Serializable {
 
-    private final long startTime;
+    private long startTime;
+    private final long warmupTime;
     private final long measurementTime;
     private final long stopTime;
     private final long warmupOps;
     private final long measurementOps;
 
-    public BenchmarkResultMetaData(long startTime, long measurementTime, long stopTime, long warmupOps, long measurementOps) {
-        this.startTime = startTime;
+    public BenchmarkResultMetaData(long warmupTime, long measurementTime, long stopTime, long warmupOps, long measurementOps) {
+        this.startTime = Long.MIN_VALUE;
+        this.warmupTime = warmupTime;
         this.measurementTime = measurementTime;
         this.stopTime = stopTime;
         this.warmupOps = warmupOps;
@@ -43,9 +45,16 @@
     }
 
     public long getStartTime() {
+        if (startTime == Long.MIN_VALUE) {
+            throw new IllegalStateException("Unset start time");
+        }
         return startTime;
     }
 
+    public long getWarmupTime() {
+        return warmupTime;
+    }
+
     public long getMeasurementTime() {
         return measurementTime;
     }
@@ -61,4 +70,8 @@
     public long getWarmupOps() {
         return warmupOps;
     }
+
+    public void adjustStart(long startTime) {
+        this.startTime = startTime;
+    }
 }
--- a/jmh-core/src/main/java/org/openjdk/jmh/runner/BaseRunner.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/runner/BaseRunner.java	Tue May 02 20:11:37 2017 +0200
@@ -84,6 +84,8 @@
             BenchmarkParams params = action.getParams();
             ActionMode mode = action.getMode();
 
+            long startTime = System.currentTimeMillis();
+
             out.startBenchmark(params);
             out.println("");
             etaBeforeBenchmark();
@@ -109,7 +111,12 @@
             doSingle(params, mode, acceptor);
 
             if (!res.isEmpty()) {
-                BenchmarkResult br = new BenchmarkResult(params, res, mds.get(0));
+                BenchmarkResultMetaData md = mds.get(0);
+                if (md != null) {
+                    md.adjustStart(startTime);
+                }
+
+                BenchmarkResult br = new BenchmarkResult(params, res, md);
                 results.put(params, br);
                 out.endBenchmark(br);
             }
@@ -237,7 +244,7 @@
     }
 
     protected void runBenchmark(BenchmarkParams benchParams, BenchmarkHandler handler, IterationResultAcceptor acceptor) {
-        long startTime = System.currentTimeMillis();
+        long warmupTime = System.currentTimeMillis();
 
         long allWarmup = 0;
         long allMeasurement = 0;
@@ -285,7 +292,7 @@
         long stopTime = System.currentTimeMillis();
 
         BenchmarkResultMetaData md = new BenchmarkResultMetaData(
-                startTime, measurementTime, stopTime,
+                warmupTime, measurementTime, stopTime,
                 allWarmup, allMeasurement);
 
         if (acceptor != null) {
--- a/jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java	Tue May 02 13:38:06 2017 +0200
+++ b/jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java	Tue May 02 20:11:37 2017 +0200
@@ -663,11 +663,17 @@
                     }
                 }
 
+                long startTime = System.currentTimeMillis();
+
                 List<IterationResult> result = doFork(server, forkedString, stdOut.file(), stdErr.file(), printOut, printErr);
                 if (!result.isEmpty()) {
                     long pid = server.getClientPid();
 
                     BenchmarkResultMetaData md = server.getMetadata();
+                    if (md != null) {
+                        md.adjustStart(startTime);
+                    }
+
                     BenchmarkResult br = new BenchmarkResult(params, result, md);
 
                     if (!profilersRev.isEmpty()) {