fix failed parsing for ZGC

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

@@ -60,8 +60,9 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     // Group 6 / tail: Pause Init Mark 1.070ms
     // Regex: ^(?:\[(?<time>[0-9-T:.+]*)])?(?:\[(?<uptime>[^s]*)s])?\[(?<level>[^]]+)]\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\((?<gcnumber>[0-9]+)\)[ ](?<type>([-.a-zA-Z ()]+|[a-zA-Z1 ()]+))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)
     //   note for the <type> part: easiest would have been to use [^0-9]+, but the G1 events don't fit there, because of the number in their name
+    //   add sub regex "[a-zA-Z ]+\\(.+\\)" for Allocation Stall and Relocation Stall of ZGC
     private static final Pattern PATTERN_DECORATORS = Pattern.compile(
-            "^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^ms]*)(?<uptimeunit>m?s)])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](GC\\((?<gcnumber>[0-9]+)\\)[ ])?(?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
+            "^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^ms]*)(?<uptimeunit>m?s)])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](GC\\((?<gcnumber>[0-9]+)\\)[ ])?(?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+|[a-zA-Z ]+\\(.+\\))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
     );
     private static final String GROUP_DECORATORS_TIME = "time";
     private static final String GROUP_DECORATORS_UPTIME = "uptime";
@@ -176,7 +177,20 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
             "Cancelling GC",
             "CDS archive(s) mapped at", // metaspace preamble since JDK 17
             "Compressed class space mapped at", // metaspace preamble since JDK 17
-            "Narrow klass base" // metaspace preamble since JDK 17
+            "Narrow klass base", // metaspace preamble since JDK 17
+            "  Mark Start  ", // heap preamble for ZGC since JDK 11
+            "Reserve:", // heap preamble for ZGC since JDK 11
+            "Free:", // heap preamble for ZGC since JDK 11
+            "Used:", // heap preamble for ZGC since JDK 11
+            "Live:", // heap preamble for ZGC since JDK 11
+            "Allocated:", // heap preamble for ZGC since JDK 11
+            "Garbage:", // heap preamble for ZGC since JDK 11
+            "Reclaimed:", // heap preamble for ZGC since JDK 11
+            "Page Cache Flushed:", // heap preamble for ZGC since JDK 11
+            "Min Capacity:", // heap preamble for ZGC since JDK 11
+            "Max Capacity:", // heap preamble for ZGC since JDK 11
+            "Soft Max Capacity:", // heap preamble for ZGC since JDK 11
+            "Uncommitted:" // heap preamble for ZGC since JDK 11
             );
     /** list of strings, that are gc log lines, but not a gc event -&gt; should be logged only */
     private static final List<String> LOG_ONLY_STRINGS = Arrays.asList("Using",
@@ -300,6 +314,19 @@ private AbstractGCEvent<?> handleTagGcPhasesTail(ParseContext context, AbstractG
 
     private AbstractGCEvent<?> handleTagGcMetaspaceTail(ParseContext context, AbstractGCEvent<?> event, String tail) {
         AbstractGCEvent<?> returnEvent = event;
+        // the event "Metaspace" in gc tag "[gc,metaspace]" for ZGC don't match the "PATTERN_MEMORY" rules; ignore it
+        // ZGC:
+        //  [1.182s][info][gc,metaspace] GC(0) Metaspace: 19M used, 19M capacity, 19M committed, 20M reserved
+        //  [1.182s][info][gc,metaspace] GC(0) Metaspace: 11M used, 12M committed, 1088M reserved
+        // G1:
+        //  [5.537s][info][gc,metaspace] GC(0) Metaspace: 118K(320K)->118K(320K) NonClass: 113K(192K)->113K(192K) Class: 4K(128K)->4K(128K)
+
+        if (returnEvent.getExtendedType().getType().equals(Type.METASPACE) && tail != null) {
+            if (tail.contains("used,") && tail.contains("committed,")) {
+                return null;
+            }
+        }
+
         returnEvent = parseTail(context, returnEvent, tail);
         // the UJL "Old" event occurs often after the next STW events have taken place; ignore it for now
         //   size after concurrent collection will be calculated by GCModel#add()

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

@@ -539,7 +539,7 @@ public String toString() {
         // since about java 7_u45 these have a time stamp prepended
         public static final Type APPLICATION_STOPPED_TIME = new Type("Total time for which application threads were stopped", Generation.OTHER, Concurrency.SERIAL, GcPattern.GC_PAUSE, CollectionType.VM_OPERATION);
         // java 8: perm gen is moved to metaspace
-        public static final Type Metaspace = new Type("Metaspace", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY);
+        public static final Type METASPACE = new Type("Metaspace", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY);
 
         // CMS types
         public static final Type CMS = new Type("CMS", Generation.TENURED);
@@ -704,13 +704,16 @@ public String toString() {
         public static final Type UJL_ZGC_PAUSE_MARK_END = new Type("Pause Mark End", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_PAUSE_RELOCATE_START = new Type("Pause Relocate Start", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_MARK = new Type("Concurrent Mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
+        public static final Type UJL_ZGC_CONCURRENT_MARK_FREE = new Type("Concurrent Mark Free", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_NONREF = new Type("Concurrent Process Non-Strong References", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_RESET_RELOC_SET = new Type("Concurrent Reset Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_DETATCHED_PAGES = new Type("Concurrent Destroy Detached Pages", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_SELECT_RELOC_SET = new Type("Concurrent Select Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_PREPARE_RELOC_SET = new Type("Concurrent Prepare Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_CONCURRENT_RELOCATE = new Type("Concurrent Relocate", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
         public static final Type UJL_ZGC_HEAP_CAPACITY = new Type("Capacity", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_HEAP_MEMORY_PERCENTAGE);
+        public static final Type UJL_ZGC_ALLOCATION_STALL = new Type("Allocation Stall", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+        public static final Type UJL_ZGC_RELOCATION_STALL = new Type("Relocation Stall", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
 
         // IBM Types
         // TODO: are scavenge always young only??

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

@@ -8,12 +8,13 @@
 import com.tagtraum.perf.gcviewer.UnittestHelper;
 import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
 import com.tagtraum.perf.gcviewer.model.GCModel;
+
 import org.junit.After;
 import org.junit.Before;
 import org.junit.Test;
 
 /**
- * Test unified java logging ZGC algorithm in OpenJDK 11
+ * Test unified java logging ZGC algorithm
  */
 public class TestDataReaderUJLZGC {
     private static final int CONCURRENT_MARK_INDEX = 0;
@@ -256,4 +257,61 @@ public void testDefaultGcSystemGc() {
                 false);
     }
 
-}
+    /** Complement other gc type tests for ZGC */
+    @Test
+    public void testGcOther() throws Exception {
+        GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
+
+        assertThat("size", model.size(), is(21));
+        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(15));
+        assertThat("amount of gc events", model.getGCPause().getN(), is(15));
+        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(0));
+        assertThat("amount of gc phases event types", model.getGcEventPhases().size(), is(3));
+        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(0));
+        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(6));
+        assertThat("total heap size", model.getHeapAllocatedSizes().getMax(), is(3884 * 1024));
+    }
+
+    @Test
+    public void testAllocationStall() throws Exception {
+        GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
+
+        AbstractGCEvent<?> allocationStallEvent = model.get(5);
+        UnittestHelper.testMemoryPauseEvent(allocationStallEvent,
+                "Allocation Stall",
+                AbstractGCEvent.Type.UJL_ZGC_ALLOCATION_STALL,
+                0.029092,
+                0, 0, 0,
+                AbstractGCEvent.Generation.TENURED,
+                false);
+    }
+
+    @Test
+    public void testRelocationStall() throws Exception {
+        GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
+
+        AbstractGCEvent<?> RelocationStallEvent = model.get(12);
+        UnittestHelper.testMemoryPauseEvent(RelocationStallEvent,
+                "Relocation Stall",
+                AbstractGCEvent.Type.UJL_ZGC_RELOCATION_STALL,
+                0.000720,
+                0, 0, 0,
+                AbstractGCEvent.Generation.TENURED,
+                false);
+    }
+
+    @Test
+    public void testConcurrentMarkFree() throws Exception {
+        GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
+
+        AbstractGCEvent<?> RelocationStallEvent = model.get(2);
+        UnittestHelper.testMemoryPauseEvent(RelocationStallEvent,
+                "Concurrent Mark Free",
+                AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_MARK_FREE,
+                0.000001,
+                0, 0, 0,
+                AbstractGCEvent.Generation.TENURED,
+                false);
+    }
+
+}

src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-other.txt

@@ -0,0 +1,37 @@
+[200.343s][info][gc,start    ] GC(25) Garbage Collection (Allocation Rate)
+[200.344s][info][gc,phases   ] GC(25) Pause Mark Start 0.008ms
+[201.482s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.1) 0.706ms
+[201.507s][info][gc,phases   ] GC(25) Concurrent Mark 1163.494ms
+[201.507s][info][gc,phases   ] GC(25) Pause Mark End 0.011ms
+[201.507s][info][gc,phases   ] GC(25) Concurrent Mark Free 0.001ms
+[201.510s][info][gc,phases   ] GC(25) Concurrent Process Non-Strong References 3.045ms
+[201.510s][info][gc,phases   ] GC(25) Concurrent Reset Relocation Set 0.072ms
+[201.511s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.10) 29.092ms
+[201.511s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.7) 11.429ms
+[201.511s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.2) 11.428ms
+[201.511s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier3}.8) 11.050ms
+[201.511s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.11) 10.880ms
+[201.511s][info][gc          ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.4) 10.660ms
+[201.519s][info][gc,phases   ] GC(25) Concurrent Select Relocation Set 8.186ms
+[201.519s][info][gc,phases   ] GC(25) Pause Relocate Start 0.006ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.3) 0.720ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.4) 0.771ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.8) 0.725ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.5) 0.672ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.10) 0.777ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.2) 0.782ms
+[201.521s][info][gc          ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.7) 0.799ms
+[201.657s][info][gc,phases   ] GC(25) Concurrent Relocate 138.752ms
+[201.658s][info][gc,metaspace] GC(25) Metaspace: 17M used, 17M committed, 1040M reserved
+[201.658s][info][gc,heap     ] GC(25) Min Capacity: 8M(0%)
+[201.658s][info][gc,heap     ] GC(25) Max Capacity: 3954M(100%)
+[201.658s][info][gc,heap     ] GC(25) Soft Max Capacity: 3954M(100%)
+[201.658s][info][gc,heap     ] GC(25)                Mark Start          Mark End        Relocate Start      Relocate End           High               Low
+[201.658s][info][gc,heap     ] GC(25)  Capacity:     3884M (98%)        3954M (100%)       3954M (100%)       3954M (100%)       3954M (100%)       3884M (98%)
+[201.658s][info][gc,heap     ] GC(25)      Free:      620M (16%)           0M (0%)           56M (1%)         1724M (44%)        1724M (44%)           0M (0%)
+[201.658s][info][gc,heap     ] GC(25)      Used:     3334M (84%)        3954M (100%)       3898M (99%)        2230M (56%)        3954M (100%)       2230M (56%)
+[201.658s][info][gc,heap     ] GC(25)      Live:         -              1359M (34%)        1359M (34%)        1359M (34%)            -                  -
+[201.658s][info][gc,heap     ] GC(25) Allocated:         -               620M (16%)         628M (16%)         691M (17%)            -                  -
+[201.658s][info][gc,heap     ] GC(25)   Garbage:         -              1974M (50%)        1910M (48%)         178M (5%)             -                  -
+[201.658s][info][gc,heap     ] GC(25) Reclaimed:         -                  -                64M (2%)         1795M (45%)            -                  -
+[201.658s][info][gc          ] GC(25) Garbage Collection (Allocation Rate) 3334M(84%)->2230M(56%)