support all of ujl decorators, allow log only contains time or uptime

Author: mayswind

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;
 
@@ -267,7 +298,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 +308,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 +516,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 +549,41 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decorator
             if (decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER) != null) {
                 event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
             }
+
+            boolean hasTime = decoratorsMatcher.group(GROUP_DECORATORS_TIME) != null;
+            boolean hasUptime = decoratorsMatcher.group(GROUP_DECORATORS_UPTIME) != null;
+
             setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
-            setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME), decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_UNIT));
+            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) {
+                hasUptime = true;
+                setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_MILLIS), "ms");
+            } 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 = true;
+                    setTimeStampIfPresent(event, String.valueOf(millisecond), "ms");
+                } else {
+                    hasTime = true;
+                    setDateStampIfPresent(event, DateHelper.formatDate(ZonedDateTime.ofInstant(Instant.ofEpochMilli(millisecond), ZoneId.systemDefault())));
+                }
+            }
+
+            // 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 = true;
+                setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_NANOS), "ns");
+            }
+
+            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));
@@ -588,6 +652,8 @@ private void setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsS
             double timestamp = NumberParser.parseDouble(timeStampAsString);
             if ("ms".equals(timeUnit)) {
                 timestamp = timestamp / 1000;
+            } else if ("ns".equals(timeUnit)) {
+                timestamp = timestamp / 1000000000;
             }
             event.setTimestamp(timestamp);
         }