enhance jdk8 parser for serial, cms and g1 printGCID events

chewiebug · Aug 29, 2022 · d74690e · d74690e
1 parent fdb2490
commit d74690e
Show file tree

Hide file tree

Showing 8 changed files with 244 additions and 8 deletions.
diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReader.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReader.java
@@ -62,7 +62,7 @@ protected DataReaderTools getDataReaderTools() {
      */
     protected boolean shouldContinue() {
         if (getLogger().isLoggable(Level.FINE)) {
-            getLogger().fine(gcResource.getResourceName() + " read cancelled");
+            getLogger().fine(gcResource.getResourceName() + " read cancelled=" + gcResource.isReadCancelled());
         }
         return !gcResource.isReadCancelled();
     }

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java
@@ -256,7 +256,7 @@ protected String parseTypeString(String line, ParseInformation pos) throws Parse
         int i = pos.getIndex();
         try {
             // consume all leading spaces and [
-            final int lineLength = line.length();
+            final int lineLength = line.length() - 1;
             final char[] lineChars = line.toCharArray();
             char c = lineChars[i];
             for (; i<lineLength; c = lineChars[++i]) {
@@ -301,14 +301,13 @@ protected String parseTypeString(String line, ParseInformation pos) throws Parse
         }
     }
 
-    // restriction PringGCID only for parallel scavenge collector
     protected void parseGcId(String line, ParseInformation pos) throws ParseException {
-        if (!line.contains("#"))
+        if (!line.substring(pos.getIndex()).contains("#"))
             return;
         int i = pos.getIndex();
         try {
             // consume all leading spaces and '#'
-            final int lineLength = line.length();
+            final int lineLength = line.length() - 1;
             final char[] lineChars = line.toCharArray();
             char c = lineChars[i];
             for (; i < lineLength; c = lineChars[++i]) {
@@ -327,7 +326,6 @@ protected void parseGcId(String line, ParseInformation pos) throws ParseExceptio
             }
         }
         finally {
-            i++;
             pos.setIndex(i);
         }
     }
@@ -542,6 +540,7 @@ protected void parseDetailEventsIfExist(final String line, final ParseInformatio
                     detailEvent.setDateStamp(datestamp);
                     detailEvent.setTimestamp(getTimestamp(line, pos, datestamp));
                 }
+                parseGcId(line, pos);
                 detailEvent.setExtendedType(parseType(line, pos));
                 if (nextIsTimestamp(line, pos) || nextIsDatestamp(line, pos)) {
                     parseDetailEventsIfExist(line, pos, detailEvent);
@@ -686,7 +685,7 @@ else if (indexOfNextClosingBracket > 0) {
 
     private int skipUntilNextDigit(String line, ParseInformation pos) throws ParseException {
         int begin = pos.getIndex();
-        while (!Character.isDigit(line.charAt(begin)) && begin < line.length()) {
+        while (!Character.isDigit(line.charAt(begin)) && begin+1 < line.length()) {
             ++begin;
         }
 

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java
@@ -58,6 +58,7 @@
  * <li>-XX:+PrintReferenceGC (output ignored)</li>
  * <li>-XX:+PrintCMSInitiationStatistics (output ignored)</li>
  * <li>-XX:+PrintFLSStatistics (output ignored)</li>
+ * <li>-XX:+PrintGCID (output ignored)</li>
  * </ul>
  *
  * @author <a href="mailto:[email protected]">Hendrik Schreiber</a>

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java
@@ -48,6 +48,7 @@
  * <li>-XX:+PrintAdaptiveSizePolicy (output ignored)</li>
  * <li>-XX:+PrintReferenceGC (output ignored)</li>
  * <li>-XX:+PrintStringDeduplicationStatistics (output ignored)</li>
+ * <li>-XX:+PrintGCID (output ignored)</li>
  * </ul>
  *
  * @author <a href="mailto:[email protected]">Joerg Wuethrich</a>
@@ -131,7 +132,7 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
 
     // the following pattern is specific for G1 with -XX:+PrintGCDetails
     // "[<datestamp>: ]0.295: [GC pause (young), 0.00594747 secs]"
-    private static final Pattern PATTERN_GC_PAUSE = Pattern.compile("^([0-9-T:.+]{29})?[ ]?([0-9.,]+)?[: \\[]{2,3}([A-Z0-9a-z- ().]+)[, ]+([0-9.,]+)[ sec\\]]+$");
+    private static final Pattern PATTERN_GC_PAUSE = Pattern.compile("^([0-9-T:.+]{29})?[ ]?([0-9.,]+)?(?:[ #0-9:]+)?[: \\[]{2,3}([A-Z0-9a-z- ().]+)[, ]+([0-9.,]+)[ sec\\]]+$");
     private static final int GC_PAUSE_GROUP_DATESTAMP = 1;
     private static final int GC_PAUSE_GROUP_TIMESTAMP = 2;
     private static final int GC_PAUSE_GROUP_TYPE = 3;

diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java
@@ -417,6 +417,30 @@ public void shenandoah_232_Beginning()  throws Exception {
                 is(1L));
     }
 
+    @Test
+    public void serialPrintGCID() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+
+        ByteArrayInputStream in = new ByteArrayInputStream(
+                ("2022-08-01T17:14:32.660+0000: 0.177: #1: [GC (Allocation Failure) 2022-08-01T17:14:32.661+0000: 0.178: #1: [DefNew: 9766K->1056K(9792K), 0.0057621 secs] 16728K->16694K(31680K), 0.0073601 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] \n" +
+                        "2022-08-01T17:14:32.671+0000: 0.188: #2: [GC (Allocation Failure) 2022-08-01T17:14:32.672+0000: 0.189: #2: [DefNew: 9746K->1056K(9792K), 0.0073505 secs]2022-08-01T17:14:32.680+0000: 0.197: #3: [Tenured: 24314K->24378K(24384K), 0.0036336 secs] 25384K->25370K(34176K), [Metaspace: 2712K->2712K(1056768K)], 0.0134215 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] \n")
+                        .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<?> secondEvent = model.get(1);
+        assertThat("name", secondEvent.getTypeAsString(), equalTo("GC (Allocation Failure); DefNew; Tenured; Metaspace"));
+        assertThat("duration", secondEvent.getPause(), closeTo(0.0134215, 0.0000001));
+        assertThat("before", secondEvent.getPreUsed(), is(25384));
+    }
+
     @Test
     public void parallelPrintGCID() throws Exception {
         TestLogHandler handler = new TestLogHandler();
@@ -432,4 +456,24 @@ public void parallelPrintGCID() throws Exception {
         assertEquals("number of errors", 0, handler.getCount());
     }
 
+    @Test
+    public void cmsPrintGCID() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("SampleSun1_8_0CmsPrintGcId.txt");
+        gcResource.getLogger().addHandler(handler);
+
+        DataReader reader = getDataReader(gcResource);
+        GCModel model = reader.read();
+
+        assertThat("gc count", model.size(), is(18));
+        assertThat("warnings", handler.getCount(), is(0));
+
+        AbstractGCEvent<?> parnew = model.get(0);
+        assertThat("name", parnew.getTypeAsString(), equalTo("GC (Allocation Failure); ParNew"));
+        assertThat("duration", parnew.getPause(), closeTo(0.0106548, 0.0000001));
+        assertThat("before", parnew.getPreUsed(), is(8678));
+
+    }
+
 }
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java
@@ -2,6 +2,7 @@
 
 import static org.hamcrest.Matchers.closeTo;
 import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertThat;
@@ -14,6 +15,7 @@
 
 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.AbstractGCEvent.Type;
 import com.tagtraum.perf.gcviewer.model.GCEvent;
 import com.tagtraum.perf.gcviewer.model.GCModel;
@@ -212,4 +214,26 @@ public void ignorePrintStringDeduplicationStatistics() throws Exception {
         assertThat("size", model.size(), is(1));
         assertThat("type", model.get(0).getExtendedType().getType(), is(Type.G1_YOUNG));
     }
+
+    @Test
+    public void printGCID() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1PrintGCID.txt");
+        gcResource.getLogger().addHandler(handler);
+
+        DataReader reader = getDataReader(gcResource);
+        GCModel model = reader.read();
+
+        assertThat("warnings", handler.getCount(), is(0));
+        assertThat("gc count", model.size(), is(11));
+
+        AbstractGCEvent<?> parnew = model.get(0);
+        assertThat("name", parnew.getTypeAsString(), equalTo("GC pause (G1 Evacuation Pause) (young)"));
+        assertThat("duration", parnew.getPause(), closeTo(0.0087570, 0.0000001));
+        assertThat("before", parnew.getPreUsed(), is(7168));
+
+    }
+
+
 }
diff --git a/src/test/resources/openjdk/SampleSun1_8_0CmsPrintGcId.txt b/src/test/resources/openjdk/SampleSun1_8_0CmsPrintGcId.txt
@@ -0,0 +1,21 @@
+OpenJDK 64-Bit Server VM (25.342-b07) for linux-amd64 JRE (1.8.0_342-b07), built on Jul 16 2022 09:19:19 by "openjdk" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
+Memory: 4k page, physical 2097152k(2094644k free), swap 3145728k(3145728k free)
+CommandLine flags: -XX:InitialHeapSize=33554432 -XX:MaxHeapSize=536870912 -XX:MaxNewSize=174485504 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCID -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
+2022-08-01T17:16:33.170+0000: 0.169: #0: [GC (Allocation Failure) 2022-08-01T17:16:33.171+0000: 0.170: #0: [ParNew: 8678K->1081K(9792K), 0.0088699 secs] 8678K->8064K(31680K), 0.0106548 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
+2022-08-01T17:16:33.185+0000: 0.185: #1: [GC (Allocation Failure) 2022-08-01T17:16:33.186+0000: 0.185: #1: [ParNew: 9760K->1056K(9792K), 0.0089566 secs] 16743K->16701K(31680K), 0.0103324 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
+2022-08-01T17:16:33.198+0000: 0.197: #2: [GC (CMS Initial Mark) [1 CMS-initial-mark: 15645K(21888K)] 18533K(31680K), 0.0010369 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
+2022-08-01T17:16:33.200+0000: 0.199: #2: [CMS-concurrent-mark-start]
+2022-08-01T17:16:33.201+0000: 0.201: #3: [GC (Allocation Failure) 2022-08-01T17:16:33.202+0000: 0.201: #3: [ParNew: 9746K->1056K(9792K), 0.0062763 secs] 25391K->25378K(34560K), 0.0073592 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
+2022-08-01T17:16:33.213+0000: 0.212: #2: [CMS-concurrent-mark: 0.005/0.013 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
+2022-08-01T17:16:33.214+0000: 0.213: #4: [GC (Allocation Failure) 2022-08-01T17:16:33.214+0000: 0.213: #4: [ParNew: 9751K->1056K(9792K), 0.0056495 secs] 34072K->34054K(43200K), 0.0064721 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
+2022-08-01T17:16:33.221+0000: 0.220: #2: [CMS-concurrent-preclean-start]
+2022-08-01T17:16:33.222+0000: 0.221: #2: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
+2022-08-01T17:16:33.222+0000: 0.222: #5: [GC (Allocation Failure) 2022-08-01T17:16:33.223+0000: 0.222: #5: [ParNew: 9754K->1056K(9792K), 0.0051785 secs] 42752K->42730K(51840K), 0.0060566 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
+2022-08-01T17:16:33.230+0000: 0.229: #2: [GC (CMS Final Remark) [YG occupancy: 1868 K (9792 K)]2022-08-01T17:16:33.230+0000: 0.230: #2: [Rescan (parallel) , 0.0007821 secs]2022-08-01T17:16:33.231+0000: 0.231: #2: [weak refs processing, 0.0004025 secs]2022-08-01T17:16:33.232+0000: 0.231: #2: [class unloading, 0.0005587 secs]2022-08-01T17:16:33.233+0000: 0.232: #2: [scrub symbol table, 0.0003980 secs]2022-08-01T17:16:33.233+0000: 0.233: #2: [scrub string table, 0.0002950 secs][1 CMS-remark: 41674K(42048K)] 43542K(51840K), 0.0039463 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
+2022-08-01T17:16:33.235+0000: 0.234: #2: [CMS-concurrent-sweep-start]
+2022-08-01T17:16:33.235+0000: 0.234: #2: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
+2022-08-01T17:16:33.235+0000: 0.235: #2: [CMS-concurrent-reset-start]
+2022-08-01T17:16:33.236+0000: 0.236: #6: [GC (Allocation Failure) 2022-08-01T17:16:33.237+0000: 0.236: #6: [ParNew: 9744K->1056K(9792K), 0.0026933 secs] 51417K->51405K(79248K), 0.0034839 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
+2022-08-01T17:16:33.244+0000: 0.243: #7: [GC (Allocation Failure) 2022-08-01T17:16:33.244+0000: 0.243: #7: [ParNew: 9745K->1056K(9792K), 0.0028328 secs] 60094K->60082K(79248K), 0.0037992 secs] [Times: user=0.00 sys=0.01, real=0.00 secs]
+2022-08-01T17:16:33.250+0000: 0.250: #8: [GC (Allocation Failure) 2022-08-01T17:16:33.251+0000: 0.250: #8: [ParNew: 9757K->1036K(9792K), 0.0016622 secs] 68783K->61918K(79248K), 0.0025883 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
+2022-08-01T17:16:33.254+0000: 0.253: #2: [CMS-concurrent-reset: 0.006/0.018 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]