#198 add support for -XX:+UseShenandoahGC in "non" unified jvm logging format

Author: chewiebug

src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java

@@ -180,7 +180,7 @@ private boolean isNumberCharacter(char character) {
                || character == ','; // some localised log files contain "," instead of "." in numbers
     }
 
-    protected void setMemory(GCEvent event, String line, ParseInformation pos) throws ParseException {
+    protected void setMemory(AbstractGCEvent<?> event, String line, ParseInformation pos) throws ParseException {
         int start = skipUntilNextDigit(line, pos);
         int end = line.indexOf("->", pos.getIndex()) - 1;
         if (end != -2) for (start = end-1; start >= 0 && Character.isDigit(line.charAt(start)); start--) {}
@@ -226,7 +226,12 @@ protected double parsePause(String line, ParseInformation pos) throws ParseExcep
         if (end < 0) {
         	end = line.indexOf(']', begin);
         }
-        final double pause = NumberParser.parseDouble(line.substring(begin, end));
+        double pause = NumberParser.parseDouble(line.substring(begin, end));
+
+        // ms...
+        if (line.endsWith("ms]")) {
+            pause = pause / 1000;
+        }
 
         // skip "secs]"
         pos.setIndex(line.indexOf(']', end) + 1);

src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java

@@ -164,7 +164,7 @@ else if (s.contains(" (young)") || s.contains("G1Ergonomics") || s.contains(" (m
             if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Sun 1.6.x G1 collector");
             return new DataReaderSun1_6_0G1(gcResource, in, GcLogType.SUN1_6G1);
         }
-        else if (s.contains("[Times:")) {
+        else if (s.contains("[Times:") || s.contains("[Pause Init Mark") /* Shenandoah, -XX:-PrintGCDetails */) {
             // all 1.6 lines end with a block like this "[Times: user=1.13 sys=0.08, real=0.95 secs]"
             if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Sun 1.6.x");
             return new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_6);

src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java

@@ -1,10 +1,5 @@
 package com.tagtraum.perf.gcviewer.imp;
 
-import com.tagtraum.perf.gcviewer.model.*;
-import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.*;
-import com.tagtraum.perf.gcviewer.util.NumberParser;
-import com.tagtraum.perf.gcviewer.util.ParseInformation;
-
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.LineNumberReader;
@@ -17,6 +12,20 @@
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.CollectionType;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Concurrency;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.GcPattern;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
+import com.tagtraum.perf.gcviewer.model.ConcurrentGCEvent;
+import com.tagtraum.perf.gcviewer.model.GCEvent;
+import com.tagtraum.perf.gcviewer.model.GCModel;
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.VmOperationEvent;
+import com.tagtraum.perf.gcviewer.util.NumberParser;
+import com.tagtraum.perf.gcviewer.util.ParseInformation;
+
 /**
  * Parses log output from Sun / Oracle Java 1.4 / 1.5 / 1.6. / 1.7 / 1.8.
  * <p>
@@ -27,6 +36,7 @@
  * <li>-XX:+UseParNewGC</li>
  * <li>-XX:+UseParallelOldGC</li>
  * <li>-XX:+UseConcMarkSweepGC</li>
+ * <li>-XX:+UseShenandoahGC</li>
  * <li>-Xincgc (1.4 / 1.5)</li>
  * </ul>
  * <p>
@@ -102,6 +112,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
         EXCLUDE_STRINGS.add("PS" + ADAPTIVE_PATTERN); // -XX:PrintAdaptiveSizePolicy
         EXCLUDE_STRINGS.add("  avg_survived_padded_avg"); // -XX:PrintAdaptiveSizePolicy
         EXCLUDE_STRINGS.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
+        EXCLUDE_STRINGS.add("Uncommitted"); // -XX:+UseShenandoahGC
+        EXCLUDE_STRINGS.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC
     }
 
     private static final String EVENT_YG_OCCUPANCY = "YG occupancy";
@@ -538,7 +550,6 @@ private boolean isCmsScavengeBeforeRemark(String line) {
     }
 
     protected AbstractGCEvent<?> parseLine(String line, ParseInformation pos) throws ParseException {
-        AbstractGCEvent<?> ae = null;
         try {
             // parse datestamp          "yyyy-MM-dd'T'hh:mm:ssZ:"
             // parse timestamp          "double:"
@@ -548,57 +559,46 @@ protected AbstractGCEvent<?> parseLine(String line, ParseInformation pos) throws
             ZonedDateTime datestamp = parseDatestamp(line, pos);
             double timestamp = getTimestamp(line, pos, datestamp);
             ExtendedType type = parseType(line, pos);
-            // special provision for CMS events
+            AbstractGCEvent<?> ae;
             if (type.getConcurrency() == Concurrency.CONCURRENT) {
                 ae = new ConcurrentGCEvent();
-                ConcurrentGCEvent event = (ConcurrentGCEvent)ae;
-
-                // simple concurrent events (ending with -start) just are of type GcPattern.GC
-                event.setDateStamp(datestamp);
-                event.setTimestamp(timestamp);
-                event.setExtendedType(type);
-                if (type.getPattern() == GcPattern.GC_PAUSE_DURATION) {
-                    // the -end events contain a pause and duration as well
-                    int start = pos.getIndex();
-                    int end = line.indexOf('/', pos.getIndex());
-                    event.setPause(NumberParser.parseDouble(line.substring(start, end)));
-                    start = end + 1;
-                    end = line.indexOf(' ', start);
-                    event.setDuration(NumberParser.parseDouble(line.substring(start, end)));
-                }
-                // nothing more to parse...
-            }
-            else if (type.getCollectionType().equals(CollectionType.VM_OPERATION)) {
+            } else if (type.getCollectionType().equals(CollectionType.VM_OPERATION)) {
                 ae = new VmOperationEvent();
-                VmOperationEvent vmOpEvent = (VmOperationEvent) ae;
-
-                vmOpEvent.setDateStamp(datestamp);
-                vmOpEvent.setTimestamp(timestamp);
-                vmOpEvent.setExtendedType(type);
-                vmOpEvent.setPause(parsePause(line, pos));
-            }
-            else {
+            } else {
                 ae = new GCEvent();
-                GCEvent event = (GCEvent) ae;
-
-                event.setDateStamp(datestamp);
-                event.setTimestamp(timestamp);
-                event.setExtendedType(type);
-                // now add detail gcevents, should they exist
-                parseDetailEventsIfExist(line, pos, event);
-                if (event.getExtendedType().getPattern() == GcPattern.GC_MEMORY_PAUSE
-                    || event.getExtendedType().getPattern() == GcPattern.GC_MEMORY) {
+            }
 
-                    setMemory(event, line, pos);
-                }
-                // then more detail events follow (perm gen is usually here)
-                parseDetailEventsIfExist(line, pos, event);
-                if (event.getExtendedType().getPattern() == GcPattern.GC_MEMORY_PAUSE
-                        || event.getExtendedType().getPattern() == GcPattern.GC_PAUSE) {
+            ae.setDateStamp(datestamp);
+            ae.setTimestamp(timestamp);
+            ae.setExtendedType(type);
+            // now add detail gcevents, should they exist
+            if (ae instanceof GCEvent) {
+                parseDetailEventsIfExist(line, pos, (GCEvent) ae);
+            }
+            if (type.getPattern() == GcPattern.GC_MEMORY_PAUSE
+                || type.getPattern() == GcPattern.GC_MEMORY) {
 
-                    event.setPause(parsePause(line, pos));
-                }
+                setMemory(ae, line, pos);
+            }
+            // then more detail events follow (perm gen is usually here)
+            if (ae instanceof GCEvent) {
+                parseDetailEventsIfExist(line, pos, (GCEvent)ae);
             }
+            if (type.getPattern() == GcPattern.GC_MEMORY_PAUSE
+                    || type.getPattern() == GcPattern.GC_PAUSE) {
+
+                ae.setPause(parsePause(line, pos));
+            } else if (type.getPattern() == GcPattern.GC_PAUSE_DURATION) {
+                // special case only occurring with concurrent collections...
+                // the -end events contain a pause and duration as well
+                int start = pos.getIndex();
+                int end = line.indexOf('/', pos.getIndex());
+                ae.setPause(NumberParser.parseDouble(line.substring(start, end)));
+                start = end + 1;
+                end = line.indexOf(' ', start);
+                ((ConcurrentGCEvent) ae).setDuration(NumberParser.parseDouble(line.substring(start, end)));
+            }
+
             return ae;
         }
         catch (RuntimeException rte) {

src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java

@@ -642,6 +642,7 @@ public String toString() {
         public static final Type UJL_SHEN_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
         public static final Type UJL_SHEN_CONCURRENT_CONC_MARK = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
         public static final Type UJL_SHEN_CONCURRENT_CONC_EVAC = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
+        public static final Type UJL_SHEN_CONCURRENT_CANCEL_CONC_MARK = new Type("Cancel concurrent mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_SHEN_CONCURRENT_CONC_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
         public static final Type UJL_SHEN_CONCURRENT_CONC_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
         public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);

src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java

@@ -323,4 +323,15 @@ public void testOracleG1J8() throws Exception {
         assertDataReader(DataReaderSun1_6_0G1.class, dr.getClass());
     }
 
+    @Test
+    public void testOracleShenandoahJ8Simple() throws Exception {
+        DataReaderFactory factory = new DataReaderFactory();
+        DataReader dr = factory.getDataReader(new GcResourceFile("byteArray"), new ByteArrayInputStream((
+                "OpenJDK 64-Bit Server VM (25.161-b14) for linux-amd64 JRE (1.8.0_161-b14), built on Jan  9 2018 19:54:33 by \"mockbuild\" with gcc 4.8.5 20150623 (Red Hat 4.8.5-16)\n" +
+                "Memory: 4k page, physical 8002012k(4357532k free), swap 2097148k(1656904k free)\n" +
+                "CommandLine flags: -XX:HeapDumpPath=/work -XX:InitialHeapSize=2147483648 -XX:LogFile=/log/jvm.log -XX:+LogVMOutput -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseNUMA -XX:+UseShenandoahGC \n" +
+                "13.976: [Pause Init Mark, 3.587 ms]\n").getBytes()));
+        assertDataReader(DataReaderSun1_6_0.class, dr.getClass());
+    }
+
 }

src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java

@@ -6,12 +6,14 @@
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertThat;
 
+import java.io.ByteArrayInputStream;
 import java.io.IOException;
 import java.io.InputStream;
 import java.util.logging.Level;
 
 import com.tagtraum.perf.gcviewer.UnittestHelper;
 import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
 import com.tagtraum.perf.gcviewer.model.GCModel;
 import com.tagtraum.perf.gcviewer.model.GCResource;
 import com.tagtraum.perf.gcviewer.model.GcResourceFile;
@@ -132,4 +134,108 @@ public void cmsPrintHeapBeforeFullGc() throws Exception {
 
         assertEquals("number of errors", 0, handler.getCount());
     }
+
+    @Test
+    public void shenandoahPauseMark() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+
+        ByteArrayInputStream in = new ByteArrayInputStream(
+                ("13.976: [Pause Init Mark, 3.587 ms]" +
+                        "\n13.992: [Pause Final Mark 1447M->684M(2048M), 2.279 ms]")
+                        .getBytes());
+
+        DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
+        GCModel model = reader.read();
+
+        assertThat("gc count", model.size(), is(2));
+        assertThat("warnings", handler.getCount(), is(0));
+
+        AbstractGCEvent<?> initMarkEvent = model.get(0);
+        assertThat("Pause init mark: name", initMarkEvent.getTypeAsString(), equalTo("Pause Init Mark"));
+        assertThat("Pause init mark: duration", initMarkEvent.getPause(), closeTo(0.003587, 0.00001));
+
+        AbstractGCEvent<?> finalMarkEvent = model.get(1);
+        assertThat("Pause final mark: name", finalMarkEvent.getTypeAsString(), equalTo("Pause Final Mark"));
+        assertThat("Pause final mark: duration", finalMarkEvent.getPause(), closeTo(0.002279, 0.00001));
+        assertThat("Pause final mark: before", finalMarkEvent.getPreUsed(), is(1447 * 1024));
+    }
+
+    @Test
+    public void shenandoahPauseUpdateRefs() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+
+        ByteArrayInputStream in = new ByteArrayInputStream(
+                ("14.001: [Pause Init Update Refs, 0.073 ms]" +
+                        "\n14.016: [Pause Final Update Refs 726M->60M(2048M), 0.899 ms]")
+                        .getBytes());
+
+        DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
+        GCModel model = reader.read();
+
+        assertThat("gc count", model.size(), is(2));
+        assertThat("warnings", handler.getCount(), is(0));
+
+        AbstractGCEvent<?> initUpdateRefsEvent = model.get(0);
+        assertThat("Pause init update refs: name", initUpdateRefsEvent.getTypeAsString(), equalTo("Pause Init Update Refs"));
+        assertThat("Pause init update refs: duration", initUpdateRefsEvent.getPause(), closeTo(0.000073, 0.0000001));
+
+        AbstractGCEvent<?> finalUpdateRefsEvent = model.get(1);
+        assertThat("Pause Final Update Refs: name", finalUpdateRefsEvent.getTypeAsString(), equalTo("Pause Final Update Refs"));
+        assertThat("Pause Final Update Refs: duration", finalUpdateRefsEvent.getPause(), closeTo(0.000899, 0.00001));
+        assertThat("Pause Final Update Refs: before", finalUpdateRefsEvent.getPreUsed(), is(726 * 1024));
+    }
+
+    @Test
+    public void shehandoahConcurrentEvents() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+
+        ByteArrayInputStream in = new ByteArrayInputStream(
+                ("13.979: [Concurrent marking 1435M->1447M(2048M), 12.576 ms]" +
+                        "\n13.994: [Concurrent evacuation 684M->712M(2048M), 6.041 ms]" +
+                        "\n14.001: [Concurrent update references  713M->726M(2048M), 14.718 ms]" +
+                        "\n14.017: [Concurrent reset bitmaps 60M->62M(2048M), 0.294 ms]" +
+                        "\n626.259: [Cancel concurrent mark, 0.056 ms]\n")
+                        .getBytes());
+
+        DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
+        GCModel model = reader.read();
+
+        assertThat("gc count", model.size(), is(5));
+        assertThat("warnings", handler.getCount(), is(0));
+
+        AbstractGCEvent<?> concurrentMarking = model.get(0);
+        assertThat("Concurrent Marking: name", concurrentMarking.getTypeAsString(), equalTo("Concurrent marking"));
+        assertThat("Concurrent Marking: duration", concurrentMarking.getPause(), closeTo(0.012576, 0.0000001));
+        assertThat("Concurrent Marking: before", concurrentMarking.getPreUsed(), is(1435 * 1024));
+        assertThat("Concurrent Marking: after", concurrentMarking.getPostUsed(), is(1447 * 1024));
+        assertThat("Concurrent Marking: total", concurrentMarking.getTotal(), is(2048 * 1024));
+    }
+
+    @Test
+    public void shenandoahIgnoredLines() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+
+        ByteArrayInputStream in = new ByteArrayInputStream(
+                ("Uncommitted 87M. Heap: 2048M reserved, 1961M committed, 992M used" +
+                        "\nCancelling concurrent GC: Allocation Failure")
+                        .getBytes());
+
+        DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
+        GCModel model = reader.read();
+
+        assertThat("gc count", model.size(), is(0));
+        assertThat("warnings", handler.getCount(), is(0));
+    }
 }