changeset 1375:bfb22e9b7ba6

Amend 7901839: Make "safepoints" profiler work on JDK 7 and 8.
author shade
date Tue, 22 Nov 2016 21:12:18 +0100
parents 65bd7d034e6b
children 9df177c239d0
files jmh-core/src/main/java/org/openjdk/jmh/profile/SafepointsProfiler.java jmh-core/src/main/java/org/openjdk/jmh/util/SampleBuffer.java jmh-core/src/test/java/org/openjdk/jmh/profile/SafepointsProfilerTest.java
diffstat 3 files changed, 112 insertions(+), 17 deletions(-) [+]
line wrap: on
line diff
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/SafepointsProfiler.java	Thu Nov 17 20:32:19 2016 +0100
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/SafepointsProfiler.java	Tue Nov 22 21:12:18 2016 +0100
@@ -33,15 +33,15 @@
 import java.io.IOException;
 import java.nio.charset.Charset;
 import java.nio.file.Files;
-import java.util.Arrays;
-import java.util.Collection;
-import java.util.Collections;
+import java.util.*;
 import java.util.concurrent.TimeUnit;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
 public class SafepointsProfiler implements ExternalProfiler {
 
+    private static final long NO_LONG_VALUE = Long.MIN_VALUE;
+
     @Override
     public String getDescription() {
         return "Safepoints profiler";
@@ -54,7 +54,16 @@
 
     @Override
     public Collection<String> addJVMOptions(BenchmarkParams params) {
-        return Collections.singletonList("-Xlog:safepoint=info");
+        return Arrays.asList(
+                // make sure old JVMs don't barf on Unified Logging
+                "-XX:+IgnoreUnrecognizedVMOptions",
+
+                // JDK 9+: preferred, Unified Logging
+                "-Xlog:safepoint=info",
+
+                // pre JDK-9: special options
+                "-XX:+PrintGCApplicationStoppedTime", "-XX:+PrintGCTimeStamps"
+        );
     }
 
     @Override
@@ -66,8 +75,7 @@
     public Collection<? extends Result> afterTrial(BenchmarkResult br, long pid, File stdOut, File stdErr) {
         long skip = br.getMetadata().getMeasurementTime() - br.getMetadata().getStartTime();
 
-        SampleBuffer pauseBuff = new SampleBuffer();
-        SampleBuffer ttspBuff = new SampleBuffer();
+        List<ParsedData> ds = new ArrayList<>();
 
         try (BufferedReader reader =
                      Files.newBufferedReader(stdOut.toPath(), Charset.defaultCharset())) {
@@ -75,19 +83,39 @@
             while ((line = reader.readLine()) != null) {
                 ParsedData data = parse(line);
                 if (data != null) {
-                    if (data.timestamp < skip) continue;
-                    pauseBuff.add(data.stopTime);
-                    ttspBuff.add(data.ttspTime);
+                    ds.add(data);
                 }
             }
         } catch (IOException e) {
             throw new IllegalStateException(e);
         }
 
-        return Arrays.asList(
-                new SafepointProfilerResult("pause", pauseBuff),
-                new SafepointProfilerResult("ttsp", ttspBuff)
-        );
+        // Only accept the lines from the highest version.
+        long maxVer = Long.MIN_VALUE;
+        for (ParsedData d : ds) {
+            maxVer = Math.max(maxVer, d.ver);
+        }
+
+        SampleBuffer pauseBuff = new SampleBuffer();
+        SampleBuffer ttspBuff = new SampleBuffer();
+
+        for (ParsedData d : ds) {
+            if (d.ver == maxVer && d.timestamp > skip) {
+                pauseBuff.add(d.stopTime);
+                if (d.ttspTime != NO_LONG_VALUE) {
+                    ttspBuff.add(d.ttspTime);
+                }
+            }
+        }
+
+        Collection<SafepointProfilerResult> results = new ArrayList<>();
+        results.add(new SafepointProfilerResult("pause", pauseBuff));
+
+        // JDK 7 does not have TTSP measurements, ignore the zero metric:
+        if (maxVer > 7) {
+            results.add(new SafepointProfilerResult("ttsp", ttspBuff));
+        }
+        return results;
     }
 
     static long parseNs(String str) {
@@ -163,16 +191,49 @@
         }
     }
 
+    private static final Pattern JDK_7_LINE =
+            Pattern.compile("([0-9\\.,]*): (.*) stopped: ([0-9\\.,]*) seconds");
+
+    private static final Pattern JDK_8_LINE =
+            Pattern.compile("([0-9\\.,]*): (.*) stopped: ([0-9\\.,]*) seconds, (.*) took: ([0-9\\.,]*) seconds");
+
+    private static final Pattern JDK_9_LINE =
+            Pattern.compile("\\[([0-9\\.,]*)s\\]\\[info\\]\\[safepoint\\] (.*) stopped: ([0-9\\.,]*) seconds, (.*) took: ([0-9\\.,]*) seconds");
+
     /**
      * Parse the line into the triplet. This is tested with unit tests, make sure to
      * update those if changing this code.
      */
     static ParsedData parse(String line) {
-        Pattern p = Pattern.compile("\\[(.*?)s\\]\\[info\\]\\[safepoint\\] (.*) stopped: (.*) seconds, (.*) took: (.*) seconds");
-        if (line.contains("[info][safepoint]")) {
-            Matcher m = p.matcher(line);
+        {
+            Matcher m = JDK_7_LINE.matcher(line);
             if (m.matches()) {
                 return new ParsedData(
+                        7,
+                        parseNs(m.group(1)),
+                        parseNs(m.group(3)),
+                        NO_LONG_VALUE
+                );
+            }
+        }
+
+        {
+            Matcher m = JDK_8_LINE.matcher(line);
+            if (m.matches()) {
+                return new ParsedData(
+                        8,
+                        parseNs(m.group(1)),
+                        parseNs(m.group(3)),
+                        parseNs(m.group(5))
+                );
+            }
+        }
+
+        {
+            Matcher m = JDK_9_LINE.matcher(line);
+            if (m.matches()) {
+                return new ParsedData(
+                        9,
                         parseNs(m.group(1)),
                         parseNs(m.group(3)),
                         parseNs(m.group(5))
@@ -184,11 +245,13 @@
     }
 
     static class ParsedData {
+        int ver;
         long timestamp;
         long stopTime;
         long ttspTime;
 
-        public ParsedData(long timestamp, long stopTime, long ttspTime) {
+        public ParsedData(int ver, long timestamp, long stopTime, long ttspTime) {
+            this.ver = ver;
             this.timestamp = timestamp;
             this.stopTime = stopTime;
             this.ttspTime = ttspTime;
--- a/jmh-core/src/main/java/org/openjdk/jmh/util/SampleBuffer.java	Thu Nov 17 20:32:19 2016 +0100
+++ b/jmh-core/src/main/java/org/openjdk/jmh/util/SampleBuffer.java	Tue Nov 22 21:12:18 2016 +0100
@@ -95,4 +95,16 @@
             }
         }
     }
+
+    public int count() {
+        int count = 0;
+        for (int[] bucket : hdr) {
+            if (bucket != null) {
+                for (int v : bucket) {
+                    count += v;
+                }
+            }
+        }
+        return count;
+    }
 }
--- a/jmh-core/src/test/java/org/openjdk/jmh/profile/SafepointsProfilerTest.java	Thu Nov 17 20:32:19 2016 +0100
+++ b/jmh-core/src/test/java/org/openjdk/jmh/profile/SafepointsProfilerTest.java	Tue Nov 22 21:12:18 2016 +0100
@@ -30,6 +30,26 @@
 public class SafepointsProfilerTest {
 
     @Test
+    public void parseJDK7u77() {
+        SafepointsProfiler.ParsedData data = SafepointsProfiler.parse(
+                "1.095: Total time for which application threads were stopped: 0.0014010 seconds");
+        Assert.assertNotNull(data);
+        Assert.assertEquals(1_095_000_000L, data.timestamp);
+        Assert.assertEquals(    1_401_000L, data.stopTime);
+        Assert.assertEquals(Long.MIN_VALUE, data.ttspTime);
+    }
+
+    @Test
+    public void parseJDK8u101() {
+        SafepointsProfiler.ParsedData data = SafepointsProfiler.parse(
+                "5.042: Total time for which application threads were stopped: 0.0028944 seconds, Stopping threads took: 0.0028351 seconds");
+        Assert.assertNotNull(data);
+        Assert.assertEquals(5_042_000_000L, data.timestamp);
+        Assert.assertEquals(    2_894_400L, data.stopTime);
+        Assert.assertEquals(    2_835_100L, data.ttspTime);
+    }
+
+    @Test
     public void parseJDK9b140() {
         SafepointsProfiler.ParsedData data = SafepointsProfiler.parse(
                 "[71.633s][info][safepoint] Total time for which application threads were stopped: 0.0359611 seconds, Stopping threads took: 0.0000516 seconds");