Merge pull request #269 from mayswind/develop

chewiebug · web-flow · commit 3c2b290e40ec · 2025-02-02T16:38:37.000+01:00
support all of unified JVM logging decorations
diff --git a/pom.xml b/pom.xml
@@ -111,6 +111,10 @@
             <name>Tony Mancill</name>
             <url>https://github.com/tmancill</url>
         </developer>
+        <developer>
+            <name>mayswind</name>
+            <url>https://github.com/mayswind</url>
+        </developer>
         <developer>
             <name>Auston McReynolds</name>
             <url>https://github.com/amcrn</url>
diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -3,6 +3,9 @@
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.UnsupportedEncodingException;
+import java.time.Instant;
+import java.time.ZoneId;
+import java.time.ZonedDateTime;
 import java.util.Arrays;
 import java.util.HashMap;
 import java.util.List;
@@ -29,13 +32,13 @@
 /**
  * DataReaderUnifiedJvmLogging can parse all gc events of unified jvm logs with default decorations.
  * <p>
- * Currently needs the "gc" selector with "info" level and "uptime,level,tags" decorators (Java 9.0.1).
+ * Currently needs the "gc" selector with "info" level and "uptime,level,tags" (or "time,level,tags") decorators (Java 9.0.1).
  * Also supports "gc*" selector with "trace" level and "time,uptime,level,tags" decorators, but will ignore some of
  * the debug and all trace level info (evaluates the following tags: "gc", "gc,start", "gc,heap", "gc,metaspace".
  * <ul>
  * <li>minimum configuration with defaults supported: <code>-Xlog:gc:file="path-to-file"</code></li>
- * <li>explicit minimum configuration needed: <code>-Xlog:gc=info:file="path-to-file":tags,uptime,level</code></li>
- * <li>maximum detail configuration this parser is able to work with: <code>-Xlog:gc*=trace:file="path-to-file":tags,time,uptime,level</code></li>
+ * <li>explicit minimum configuration needed: <code>-Xlog:gc=info:file="path-to-file":uptime,level,tags</code> or <code>-Xlog:gc=info:file="path-to-file":time,level,tags</code></li>
+ * <li>maximum detail configuration this parser is able to work with: <code>-Xlog:gc*=trace:file="path-to-file":time,uptime,timemillis,uptimemillis,timenanos,uptimenanos,pid,tid,level,tags</code></li>
  * </ul>
  * Only processes the following information format for Serial, Parallel, CMS, G1 and Shenandoah algorithms, everything else is ignored:
  * <pre>
@@ -51,28 +54,56 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     // TODO also parse "Allocation Stall (main)" events
 
     // matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
-    // Input: [0.693s][info][gc           ] GC(0) Pause Init Mark 1.070ms
-    // Group 1 / time: <empty> (optional group, no full timestamp present)
-    // Group 2 / uptime: 0.693 (optional group, present in this example)
-    // Group 3 / level: info
-    // Group 4 / tags: gc
-    // Group 5 / gcnumber: 0
-    // 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}.*))|$)
+    // Input: [2023-01-01T00:00:14.206+0000][14.206s][1672531214206ms][14205ms][1000014205707082ns][14205707082ns][6000][6008][info ][gc                      ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 4115M->103M(8192M) 28.115ms
+    // reference: https://openjdk.org/jeps/158
+    // Group  1 / time: 2023-01-01T00:00:14.206+0800 (Current time and date in ISO-8601 format)
+    // Group  2 / uptime: 14.206s (Time since the start of the JVM in seconds and milliseconds)
+    // Group  3 / timemillis: 1672531214206ms (The same value as generated by System.currentTimeMillis())
+    // Group  4 / uptimemillis: 14205ms (Milliseconds since the JVM started)
+    // Group  5 / timenanos: 1000014205707082ns (The same value as generated by System.nanoTime())
+    // Group  6 / uptimenanos: 14205707082ns (Nanoseconds since the JVM started)
+    // Group  7 / pid: 6000 (The process identifier)
+    // Group  8 / tid: 6008 (The thread identifier)
+    // Group  9 / level: info (The level associated with the log message)
+    // Group 10 / tags: gc (The tag-set associated with the log message)
+    // Group 11 / gcnumber: 0
+    // Group 12 / tail: Pause Init Mark 1.070ms
+    // Regex: (see the below)
     //   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 ()]+|[a-zA-Z ]+\\(.+\\))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
+            "^" +
+                    "(?:\\[(?<time>[0-9-T:.+]*)])?" +
+                    "(?:\\[(?<uptime>[0-9.,]+)s[ ]*])?" +
+                    "(?:\\[(?<timemillis>[0-9]+)ms[ ]*])?" +
+                    "(?:\\[(?<uptimemillis>[0-9]+)ms[ ]*])?" +
+                    "(?:\\[(?<timenanos>[0-9]+)ns[ ]*])?" +
+                    "(?:\\[(?<uptimenanos>[0-9]+)ns[ ]*])?" +
+                    "(?:\\[(?<pid>[0-9]+)[ ]*])?" +
+                    "(?:\\[(?<tid>[0-9]+)[ ]*])?" +
+                    "\\[(?<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";
-    private static final String GROUP_DECORATORS_UPTIME_UNIT = "uptimeunit";
+    private static final String GROUP_DECORATORS_TIME_MILLIS = "timemillis";
+    private static final String GROUP_DECORATORS_UPTIME_MILLIS = "uptimemillis";
+    private static final String GROUP_DECORATORS_TIME_NANOS = "timenanos";
+    private static final String GROUP_DECORATORS_UPTIME_NANOS = "uptimenanos";
+    private static final String GROUP_DECORATORS_PID = "pid";
+    private static final String GROUP_DECORATORS_TID = "tid";
     private static final String GROUP_DECORATORS_LEVEL = "level";
     private static final String GROUP_DECORATORS_TAGS = "tags";
     private static final String GROUP_DECORATORS_GC_NUMBER = "gcnumber";
     private static final String GROUP_DECORATORS_GC_TYPE = "type";
     private static final String GROUP_DECORATORS_TAIL = "tail";
 
+    private static final long MIN_VALID_UNIX_TIME_MILLIS = 1000000000000L; // 2001-09-09 09:46:40
+
     private static final Pattern PATTERN_HEAP_REGION_SIZE = Pattern.compile("^Heap [Rr]egion [Ss]ize: ([0-9]+)M$");
     private static final int GROUP_HEAP_REGION_SIZE = 1;
 
@@ -174,6 +205,7 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
             "[trace",
             "gc,heap,coops",
             "gc,heap,exit",
+            "gc,metaspace,freelist,oom",
             "[gc,phases,start",
             "Trigger: ",
             "Failed to allocate",
@@ -267,7 +299,7 @@ private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> e
                 returnEvent = handleTagGcHeapTail(context, event, tail);
                 // ZGC heap capacity, break out and handle next event
                 if (returnEvent == null) {
-                    break;
+                break;
                 }
                 // fallthrough -> same handling as for METASPACE event
             case TAG_GC_METASPACE:
@@ -277,8 +309,8 @@ private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> e
                 returnEvent = handleTagGcTail(context, event, tail);
                 break;
             case TAG_GC_PHASES:
-            	returnEvent = handleTagGcPhasesTail(context, event, tail);
-            	break;
+                returnEvent = handleTagGcPhasesTail(context, event, tail);
+                break;
             default:
                 getLogger().warning(String.format("Unexpected tail present in the end of line number %d (tail=\"%s\"; line=\"%s\")", in.getLineNumber(), tail, context.getLine()));
         }
@@ -485,7 +517,7 @@ private void parseGcMemoryPercentageTail(ParseContext context, AbstractGCEvent<?
             // the end Garbage Collection tags in ZGC contain details of memory cleaned up
             // and the percentage of memory used before and after clean. The details can be used to 
             // determine Allocation rate.
-        	setMemoryWithPercentage(event, memoryPercentageMatcher);
+            setMemoryWithPercentage(event, memoryPercentageMatcher);
         } else {
             getLogger().warning(String.format("Expected memory percentage in the end of line number %d (line=\"%s\")", in.getLineNumber(), context.getLine()));
         }
@@ -518,8 +550,39 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decorator
             if (decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER) != null) {
                 event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
             }
-            setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
-            setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME), decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_UNIT));
+
+            boolean hasTime = setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
+            boolean hasUptime = setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME), "s");
+
+            // The second time is the uptime for sure when the text contains two pairs of millisecond time
+            if (decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS) != null && decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_MILLIS) != null) {
+                if (!hasTime) {
+                    long timeInMillisecond = Long.parseLong(decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS));
+                    hasTime = setDateStampIfPresent(event, DateHelper.formatDate(ZonedDateTime.ofInstant(Instant.ofEpochMilli(timeInMillisecond), ZoneId.systemDefault()))) || hasTime;
+                }
+
+                hasUptime = setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_MILLIS), "ms") || hasUptime;
+            } else if (decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS) != null) {
+                // If the first millisecond time below the valid unix time, it may be uptime, otherwise it may be unix time
+                long millisecond = Long.parseLong(decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS));
+
+                if (millisecond < MIN_VALID_UNIX_TIME_MILLIS) {
+                    hasUptime = setTimeStampIfPresent(event, String.valueOf(millisecond), "ms") || hasUptime;
+                } else {
+                    hasTime = setDateStampIfPresent(event, DateHelper.formatDate(ZonedDateTime.ofInstant(Instant.ofEpochMilli(millisecond), ZoneId.systemDefault()))) || hasTime;
+                }
+            }
+
+            // The second time is the uptime for sure only if the text contains two pairs of nanosecond time
+            if (decoratorsMatcher.group(GROUP_DECORATORS_TIME_NANOS) != null && decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_NANOS) != null) {
+                hasUptime = setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_NANOS), "ns") || hasUptime;
+            }
+
+            if (!hasTime && !hasUptime) {
+                getLogger().warning(String.format("Failed to parse line number %d (no valid time or timestamp; line=\"%s\")", in.getLineNumber(), line));
+                return null;
+            }
+
             return event;
         } else {
             getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
@@ -576,21 +639,27 @@ private void setMemoryWithPercentage(AbstractGCEvent<?> event, Matcher matcher)
         }
     }
 
-    private void setDateStampIfPresent(AbstractGCEvent<?> event, String dateStampAsString) {
+    private boolean setDateStampIfPresent(AbstractGCEvent<?> event, String dateStampAsString) {
         // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
         if (dateStampAsString != null) {
             event.setDateStamp(DateHelper.parseDate(dateStampAsString));
+            return true;
         }
+        return false;
     }
 
-    private void setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsString, String timeUnit) {
+    private boolean setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsString, String timeUnit) {
         if (timeStampAsString != null && timeStampAsString.length() > 0) {
             double timestamp = NumberParser.parseDouble(timeStampAsString);
             if ("ms".equals(timeUnit)) {
                 timestamp = timestamp / 1000;
+            } else if ("ns".equals(timeUnit)) {
+                timestamp = timestamp / 1000000000;
             }
             event.setTimestamp(timestamp);
+            return true;
         }
+        return false;
     }
 
     private boolean isExcludedLine(String line) {
diff --git a/src/main/java/com/tagtraum/perf/gcviewer/view/AboutDialog.java b/src/main/java/com/tagtraum/perf/gcviewer/view/AboutDialog.java
@@ -60,6 +60,7 @@ public class AboutDialog extends ScreenCenteredDialog implements ActionListener
         "James Livingston",
         "Mart Mägi",
         "Tony Mancill",
+        "mayswind",
         "Auston McReynolds",
         "Samuel Mendenhall",
         "Carl Meyer",
@@ -97,7 +98,7 @@ public AboutDialog(Frame f) {
         versionPanel.setBorder(BorderFactory.createEmptyBorder(10, 10, 10, 10));
         versionPanel.setLayout(new GridBagLayout());
 
-        JLabel copyright = new JLabel("\u00A9" + " 2011-2022: Joerg Wuethrich and contributors", JLabel.CENTER);
+        JLabel copyright = new JLabel("\u00A9" + " 2011-2025: Joerg Wuethrich and contributors", JLabel.CENTER);
 
         JLabel contributorsLabel = new JLabel("contributors (alphabetically ordered):", JLabel.CENTER);
         contributorsLabel.setForeground(Color.GRAY);
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLDecorations.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLDecorations.java
