Skip to content

Commit

Permalink
support all of ujl decorators, allow log only contains time or uptime
Browse files Browse the repository at this point in the history
  • Loading branch information
@mayswind
mayswind committed Apr 25, 2023
1 parent af97692 commit d9088d2
Show file tree
Hide file tree
Showing 2 changed files with 260 additions and 18 deletions.
102 changes: 84 additions & 18 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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>
Expand All @@ -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;

Expand Down Expand Up @@ -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:
Expand All @@ -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()));
}
Expand Down Expand Up @@ -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()));
}
Expand Down Expand Up @@ -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));
Expand Down Expand Up @@ -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);
}
Expand Down
Loading

0 comments on commit d9088d2

Please sign in to comment.