changeset 1389:d6f22497f8b4

7901861: perf* profilers should use measured time to filter events
author shade
date Tue, 06 Dec 2016 12:05:41 +0100
parents 49b0a822bc1f
children d548e3fb7337
files jmh-core/src/main/java/org/openjdk/jmh/profile/AbstractPerfAsmProfiler.java jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfAsmProfiler.java jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfNormProfiler.java jmh-core/src/main/java/org/openjdk/jmh/profile/WinPerfAsmProfiler.java
diffstat 4 files changed, 92 insertions(+), 24 deletions(-) [+]
line wrap: on
line diff
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/AbstractPerfAsmProfiler.java	Mon Dec 05 20:50:17 2016 +0100
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/AbstractPerfAsmProfiler.java	Tue Dec 06 12:05:41 2016 +0100
@@ -34,7 +34,6 @@
 
 import java.io.*;
 import java.util.*;
-import java.util.concurrent.TimeUnit;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
@@ -48,6 +47,7 @@
     private final int printMargin;
     private final int mergeMargin;
     private final int delayMsec;
+    private final int lengthMsec;
 
     private final boolean skipAssembly;
     private final boolean skipInterpreter;
@@ -117,6 +117,10 @@
                         "Delay collection for a given time, in milliseconds; -1 to detect automatically.")
                 .withRequiredArg().ofType(Integer.class).describedAs("ms").defaultsTo(-1);
 
+        OptionSpec<Integer> optLength = parser.accepts("length",
+                        "Do the collection for a given time, in milliseconds; -1 to detect automatically.")
+                .withRequiredArg().ofType(Integer.class).describedAs("ms").defaultsTo(-1);
+
         OptionSpec<Boolean> optSkipAsm = parser.accepts("skipAsm",
                         "Skip -XX:+PrintAssembly instrumentation.")
                 .withRequiredArg().ofType(Boolean.class).describedAs("bool").defaultsTo(false);
@@ -196,6 +200,7 @@
             printMargin = set.valueOf(optPrintMargin);
             mergeMargin = set.valueOf(optMergeMargin);
             delayMsec = set.valueOf(optDelay);
+            lengthMsec = set.valueOf(optLength);
 
             skipAssembly = set.valueOf(optSkipAsm);
             skipInterpreter = set.valueOf(optSkipInterpreter);
@@ -288,10 +293,11 @@
     /**
      * Read parsed events.
      *
-     * @param skipSec Seconds to skip.
+     * @param skipMs Milliseconds to skip.
+     * @param lenMs Milliseconds to capture after skip
      * @return Events.
      */
-    protected abstract PerfEvents readEvents(double skipSec);
+    protected abstract PerfEvents readEvents(double skipMs, double lenMs);
 
     /**
      * Get perf binary data extension (optional).
@@ -331,19 +337,24 @@
          * 3. Read out perf output
          */
 
-        long delayNs;
+        long skipMs;
         if (delayMsec == -1) { // not set
-            delayNs = TimeUnit.MILLISECONDS.toNanos(ProfilerUtils.warmupDelayMs(br));
+            skipMs = ProfilerUtils.warmupDelayMs(br);
         } else {
-            delayNs = TimeUnit.MILLISECONDS.toNanos(delayMsec);
+            skipMs = delayMsec;
         }
 
-        double skipSec = 1.0 * delayNs / TimeUnit.SECONDS.toNanos(1);
+        double lenMs;
+        if (lengthMsec == -1) { // not set
+            lenMs = ProfilerUtils.measuredTimeMs(br);
+        } else {
+            lenMs = lengthMsec;
+        }
 
-        final PerfEvents events = readEvents(skipSec);
+        final PerfEvents events = readEvents(skipMs, lenMs);
 
         if (!events.isEmpty()) {
-            pw.printf("Perf output processed (skipped %.3f seconds):%n", skipSec);
+            pw.printf("Perf output processed (skipped %.3f seconds):%n", skipMs / 1000D);
             int cnt = 1;
             for (String event : this.events) {
                 pw.printf(" Column %d: %s (%d events)%n", cnt, event, events.get(event).size());
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfAsmProfiler.java	Mon Dec 05 20:50:17 2016 +0100
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfAsmProfiler.java	Tue Dec 06 12:05:41 2016 +0100
@@ -98,7 +98,10 @@
     }
 
     @Override
-    protected PerfEvents readEvents(double skipSec) {
+    protected PerfEvents readEvents(double skipMs, double lenMs) {
+        double readFrom = skipMs / 1000D;
+        double readTo = (skipMs + lenMs) / 1000D;
+
         try (FileReader fr = new FileReader(perfParsedData);
              BufferedReader reader = new BufferedReader(fr)) {
             Deduplicator<MethodDesc> dedup = new Deduplicator<>();
@@ -139,7 +142,10 @@
                     if (startTime == null) {
                         startTime = time;
                     } else {
-                        if (time - startTime < skipSec) {
+                        if (time - startTime < readFrom) {
+                            continue;
+                        }
+                        if (time - startTime > readTo) {
                             continue;
                         }
                     }
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfNormProfiler.java	Mon Dec 05 20:50:17 2016 +0100
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfNormProfiler.java	Tue Dec 06 12:05:41 2016 +0100
@@ -61,6 +61,7 @@
     };
 
     private final int delayMs;
+    private final int lengthMs;
     private final boolean useDefaultStats;
     private final long highPassFilter;
     private final int incrementInterval;
@@ -80,6 +81,10 @@
                         "Delay collection for a given time, in milliseconds; -1 to detect automatically.")
                 .withRequiredArg().ofType(Integer.class).describedAs("ms").defaultsTo(-1);
 
+        OptionSpec<Integer> optLength = parser.accepts("length",
+                "Do the collection for a given time, in milliseconds; -1 to detect automatically.")
+                .withRequiredArg().ofType(Integer.class).describedAs("ms").defaultsTo(-1);
+
         OptionSpec<Integer> optIncrementInterval = parser.accepts("interval",
                         "The interval between incremental updates from a concurrently running perf. " +
                         "Lower values may improve accuracy, while increasing the profiling overhead.")
@@ -99,6 +104,7 @@
 
         try {
             delayMs = set.valueOf(optDelay);
+            lengthMs = set.valueOf(optLength);
             incrementInterval = set.valueOf(optIncrementInterval);
             highPassFilter = set.valueOf(optHighPassFilter);
             useDefaultStats = set.valueOf(optDefaultStat);
@@ -176,21 +182,29 @@
         return "Linux perf statistics, normalized by operation count";
     }
 
-    public long getDelay(BenchmarkResult br) {
-        if (delayMs == -1) { // not set
-            return TimeUnit.MILLISECONDS.toNanos(ProfilerUtils.warmupDelayMs(br));
-        } else {
-            return TimeUnit.MILLISECONDS.toNanos(delayMs);
-        }
-    }
-
     private Collection<? extends Result> process(BenchmarkResult br, File stdOut, File stdErr) {
         Multiset<String> events = new HashMultiset<>();
 
         try (FileReader fr = new FileReader(stdErr);
              BufferedReader reader = new BufferedReader(fr)) {
 
-            long delayNs = getDelay(br);
+            long skipMs;
+            if (delayMs == -1) { // not set
+                skipMs = ProfilerUtils.warmupDelayMs(br);
+            } else {
+                skipMs = delayMs;
+            }
+
+            double lenMs;
+            if (lengthMs == -1) { // not set
+                lenMs = ProfilerUtils.measuredTimeMs(br);
+            } else {
+                lenMs = lengthMs;
+            }
+
+            double readFrom = skipMs / 1000D;
+            double softTo = (skipMs + lenMs) / 1000D;
+            double readTo = (skipMs + lenMs + incrementInterval) / 1000D;
 
             NumberFormat nf = NumberFormat.getInstance();
 
@@ -222,12 +236,44 @@
                         continue nextline;
                     }
 
+                    double multiplier = 1D;
                     try {
                         double timeSec = nf.parse(time).doubleValue();
-                        if (timeSec * TimeUnit.SECONDS.toNanos(1) < delayNs) {
+                        if (timeSec < readFrom) {
                             // warmup, ignore
                             continue nextline;
                         }
+                        if (timeSec > readTo) {
+                            // post-run, ignore
+                            continue nextline;
+                        }
+
+                        // Handle partial events:
+                        double intervalSec = incrementInterval / 1000D;
+                        if (timeSec - intervalSec < readFrom) {
+                            // Event _starts_ before the measurement window
+                            //     .............[============|============
+                            //               readFrom     timeSec
+                            //           [<----------------->|  // event
+                            //             incrementInterval
+                            //
+                            // Only count the tail after readFrom:
+
+                            multiplier = (timeSec - readFrom) / intervalSec;
+                        }
+                        if (timeSec > softTo) {
+                            // Event is past the measurement window
+                            //    =============].............|............
+                            //               softTo       timeSec
+                            //           [<----------------->|  // event
+                            //             incrementInterval
+                            //
+                            // Only count the head before softTo:
+                            multiplier = 1 - (timeSec - softTo) / intervalSec;
+                        }
+
+                        // Defensive, keep multiplier in bounds:
+                        multiplier = Math.max(1D, Math.min(0D, multiplier));
                     } catch (ParseException e) {
                         // don't care then, continue
                         continue nextline;
@@ -239,7 +285,7 @@
                             // anomalous value, pretend we did not see it
                             continue nextline;
                         }
-                        events.add(event, lValue);
+                        events.add(event, (long) (lValue * multiplier));
                     } catch (ParseException e) {
                         // do nothing, continue
                         continue nextline;
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/WinPerfAsmProfiler.java	Mon Dec 05 20:50:17 2016 +0100
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/WinPerfAsmProfiler.java	Tue Dec 06 12:05:41 2016 +0100
@@ -178,7 +178,10 @@
     }
 
     @Override
-    protected PerfEvents readEvents(double skipSec) {
+    protected PerfEvents readEvents(double skipMs, double lenMs) {
+        double readFrom = skipMs / 1000D;
+        double readTo = (skipMs + lenMs) / 1000D;
+
         try (FileReader fr = new FileReader(perfParsedData);
              BufferedReader reader = new BufferedReader(fr)) {
             Deduplicator<MethodDesc> dedup = new Deduplicator<>();
@@ -220,7 +223,9 @@
 
                 double time = Double.valueOf(timeStr) / 1000000;
 
-                if (time < skipSec)
+                if (time < readFrom)
+                    continue;
+                if (time > readTo)
                     continue;
 
                 // Get address.