Skip to content

Commit 6940be0

Browse files
mayswindmayswind
committedJun 9, 2023
support all of ujl decorators, allow log only contains time or uptime
1 parent af97692 commit 6940be0

File tree

2 files changed

+476
-21
lines changed

2 files changed

+476
-21
lines changed
 

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

+89-21
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,9 @@
33
import java.io.IOException;
44
import java.io.InputStream;
55
import java.io.UnsupportedEncodingException;
6+
import java.time.Instant;
7+
import java.time.ZoneId;
8+
import java.time.ZonedDateTime;
69
import java.util.Arrays;
710
import java.util.HashMap;
811
import java.util.List;
@@ -29,13 +32,13 @@
2932
/**
3033
* DataReaderUnifiedJvmLogging can parse all gc events of unified jvm logs with default decorations.
3134
* <p>
32-
* Currently needs the "gc" selector with "info" level and "uptime,level,tags" decorators (Java 9.0.1).
35+
* Currently needs the "gc" selector with "info" level and "uptime,level,tags" (or "time,level,tags") decorators (Java 9.0.1).
3336
* Also supports "gc*" selector with "trace" level and "time,uptime,level,tags" decorators, but will ignore some of
3437
* the debug and all trace level info (evaluates the following tags: "gc", "gc,start", "gc,heap", "gc,metaspace".
3538
* <ul>
3639
* <li>minimum configuration with defaults supported: <code>-Xlog:gc:file="path-to-file"</code></li>
37-
* <li>explicit minimum configuration needed: <code>-Xlog:gc=info:file="path-to-file":tags,uptime,level</code></li>
38-
* <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>
40+
* <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>
41+
* <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>
3942
* </ul>
4043
* Only processes the following information format for Serial, Parallel, CMS, G1 and Shenandoah algorithms, everything else is ignored:
4144
* <pre>
@@ -51,28 +54,56 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
5154
// TODO also parse "Allocation Stall (main)" events
5255

5356
// matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
54-
// Input: [0.693s][info][gc ] GC(0) Pause Init Mark 1.070ms
55-
// Group 1 / time: <empty> (optional group, no full timestamp present)
56-
// Group 2 / uptime: 0.693 (optional group, present in this example)
57-
// Group 3 / level: info
58-
// Group 4 / tags: gc
59-
// Group 5 / gcnumber: 0
60-
// Group 6 / tail: Pause Init Mark 1.070ms
61-
// 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}.*))|$)
57+
// 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
58+
// reference: https://openjdk.org/jeps/158
59+
// Group 1 / time: 2023-01-01T00:00:14.206+0800 (Current time and date in ISO-8601 format)
60+
// Group 2 / uptime: 14.206s (Time since the start of the JVM in seconds and milliseconds)
61+
// Group 3 / timemillis: 1672531214206ms (The same value as generated by System.currentTimeMillis())
62+
// Group 4 / uptimemillis: 14205ms (Milliseconds since the JVM started)
63+
// Group 5 / timenanos: 1000014205707082ns (The same value as generated by System.nanoTime())
64+
// Group 6 / uptimenanos: 14205707082ns (Nanoseconds since the JVM started)
65+
// Group 7 / pid: 6000 (The process identifier)
66+
// Group 8 / tid: 6008 (The thread identifier)
67+
// Group 9 / level: info (The level associated with the log message)
68+
// Group 10 / tags: gc (The tag-set associated with the log message)
69+
// Group 11 / gcnumber: 0
70+
// Group 12 / tail: Pause Init Mark 1.070ms
71+
// Regex: (see the below)
6272
// 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
6373
// add sub regex "[a-zA-Z ]+\\(.+\\)" for Allocation Stall and Relocation Stall of ZGC
6474
private static final Pattern PATTERN_DECORATORS = Pattern.compile(
65-
"^(?:\\[(?<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}.*))|$)"
75+
"^" +
76+
"(?:\\[(?<time>[0-9-T:.+]*)])?" +
77+
"(?:\\[(?<uptime>[0-9.,]+)s[ ]*])?" +
78+
"(?:\\[(?<timemillis>[0-9]+)ms[ ]*])?" +
79+
"(?:\\[(?<uptimemillis>[0-9]+)ms[ ]*])?" +
80+
"(?:\\[(?<timenanos>[0-9]+)ns[ ]*])?" +
81+
"(?:\\[(?<uptimenanos>[0-9]+)ns[ ]*])?" +
82+
"(?:\\[(?<pid>[0-9]+)[ ]*])?" +
83+
"(?:\\[(?<tid>[0-9]+)[ ]*])?" +
84+
"\\[(?<level>[^]]+)]" +
85+
"\\[(?:(?<tags>[^] ]+)[ ]*)]" +
86+
"[ ]" +
87+
"(GC\\((?<gcnumber>[0-9]+)\\)[ ])?" +
88+
"(?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+|[a-zA-Z ]+\\(.+\\))" +
89+
"(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
6690
);
6791
private static final String GROUP_DECORATORS_TIME = "time";
6892
private static final String GROUP_DECORATORS_UPTIME = "uptime";
69-
private static final String GROUP_DECORATORS_UPTIME_UNIT = "uptimeunit";
93+
private static final String GROUP_DECORATORS_TIME_MILLIS = "timemillis";
94+
private static final String GROUP_DECORATORS_UPTIME_MILLIS = "uptimemillis";
95+
private static final String GROUP_DECORATORS_TIME_NANOS = "timenanos";
96+
private static final String GROUP_DECORATORS_UPTIME_NANOS = "uptimenanos";
97+
private static final String GROUP_DECORATORS_PID = "pid";
98+
private static final String GROUP_DECORATORS_TID = "tid";
7099
private static final String GROUP_DECORATORS_LEVEL = "level";
71100
private static final String GROUP_DECORATORS_TAGS = "tags";
72101
private static final String GROUP_DECORATORS_GC_NUMBER = "gcnumber";
73102
private static final String GROUP_DECORATORS_GC_TYPE = "type";
74103
private static final String GROUP_DECORATORS_TAIL = "tail";
75104

105+
private static final long MIN_VALID_UNIX_TIME_MILLIS = 1000000000000L; // 2001-09-09 09:46:40
106+
76107
private static final Pattern PATTERN_HEAP_REGION_SIZE = Pattern.compile("^Heap [Rr]egion [Ss]ize: ([0-9]+)M$");
77108
private static final int GROUP_HEAP_REGION_SIZE = 1;
78109

@@ -267,7 +298,7 @@ private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> e
267298
returnEvent = handleTagGcHeapTail(context, event, tail);
268299
// ZGC heap capacity, break out and handle next event
269300
if (returnEvent == null) {
270-
break;
301+
break;
271302
}
272303
// fallthrough -> same handling as for METASPACE event
273304
case TAG_GC_METASPACE:
@@ -277,8 +308,8 @@ private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> e
277308
returnEvent = handleTagGcTail(context, event, tail);
278309
break;
279310
case TAG_GC_PHASES:
280-
returnEvent = handleTagGcPhasesTail(context, event, tail);
281-
break;
311+
returnEvent = handleTagGcPhasesTail(context, event, tail);
312+
break;
282313
default:
283314
getLogger().warning(String.format("Unexpected tail present in the end of line number %d (tail=\"%s\"; line=\"%s\")", in.getLineNumber(), tail, context.getLine()));
284315
}
@@ -485,7 +516,7 @@ private void parseGcMemoryPercentageTail(ParseContext context, AbstractGCEvent<?
485516
// the end Garbage Collection tags in ZGC contain details of memory cleaned up
486517
// and the percentage of memory used before and after clean. The details can be used to
487518
// determine Allocation rate.
488-
setMemoryWithPercentage(event, memoryPercentageMatcher);
519+
setMemoryWithPercentage(event, memoryPercentageMatcher);
489520
} else {
490521
getLogger().warning(String.format("Expected memory percentage in the end of line number %d (line=\"%s\")", in.getLineNumber(), context.getLine()));
491522
}
@@ -518,8 +549,39 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decorator
518549
if (decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER) != null) {
519550
event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
520551
}
521-
setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
522-
setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME), decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_UNIT));
552+
553+
boolean hasTime = setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
554+
boolean hasUptime = setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME), "s");
555+
556+
// The second time is the uptime for sure when the text contains two pairs of millisecond time
557+
if (decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS) != null && decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_MILLIS) != null) {
558+
if (!hasTime) {
559+
long timeInMillisecond = Long.parseLong(decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS));
560+
hasTime = setDateStampIfPresent(event, DateHelper.formatDate(ZonedDateTime.ofInstant(Instant.ofEpochMilli(timeInMillisecond), ZoneId.systemDefault()))) || hasTime;
561+
}
562+
563+
hasUptime = setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_MILLIS), "ms") || hasUptime;
564+
} else if (decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS) != null) {
565+
// If the first millisecond time below the valid unix time, it may be uptime, otherwise it may be unix time
566+
long millisecond = Long.parseLong(decoratorsMatcher.group(GROUP_DECORATORS_TIME_MILLIS));
567+
568+
if (millisecond < MIN_VALID_UNIX_TIME_MILLIS) {
569+
hasUptime = setTimeStampIfPresent(event, String.valueOf(millisecond), "ms") || hasUptime;
570+
} else {
571+
hasTime = setDateStampIfPresent(event, DateHelper.formatDate(ZonedDateTime.ofInstant(Instant.ofEpochMilli(millisecond), ZoneId.systemDefault()))) || hasTime;
572+
}
573+
}
574+
575+
// The second time is the uptime for sure only if the text contains two pairs of nanosecond time
576+
if (decoratorsMatcher.group(GROUP_DECORATORS_TIME_NANOS) != null && decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_NANOS) != null) {
577+
hasUptime = setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_NANOS), "ns") || hasUptime;
578+
}
579+
580+
if (!hasTime && !hasUptime) {
581+
getLogger().warning(String.format("Failed to parse line number %d (no valid time or timestamp; line=\"%s\")", in.getLineNumber(), line));
582+
return null;
583+
}
584+
523585
return event;
524586
} else {
525587
getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
@@ -576,21 +638,27 @@ private void setMemoryWithPercentage(AbstractGCEvent<?> event, Matcher matcher)
576638
}
577639
}
578640

579-
private void setDateStampIfPresent(AbstractGCEvent<?> event, String dateStampAsString) {
641+
private boolean setDateStampIfPresent(AbstractGCEvent<?> event, String dateStampAsString) {
580642
// TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
581643
if (dateStampAsString != null) {
582644
event.setDateStamp(DateHelper.parseDate(dateStampAsString));
645+
return true;
583646
}
647+
return false;
584648
}
585649

586-
private void setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsString, String timeUnit) {
650+
private boolean setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsString, String timeUnit) {
587651
if (timeStampAsString != null && timeStampAsString.length() > 0) {
588652
double timestamp = NumberParser.parseDouble(timeStampAsString);
589653
if ("ms".equals(timeUnit)) {
590654
timestamp = timestamp / 1000;
655+
} else if ("ns".equals(timeUnit)) {
656+
timestamp = timestamp / 1000000000;
591657
}
592658
event.setTimestamp(timestamp);
659+
return true;
593660
}
661+
return false;
594662
}
595663

596664
private boolean isExcludedLine(String line) {

0 commit comments

Comments
 (0)