Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

support all of unified JVM logging decorations #269

Open
wants to merge 2 commits into
base: develop
Choose a base branch
from
Open

support all of unified JVM logging decorations #269

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
6940be0
support all of ujl decorators, allow log only contains time or uptime
mayswind Apr 25, 2023
ba5c9b8
exclude oom log
mayswind Jun 9, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
111 changes: 90 additions & 21 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
View file
Open in desktop
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 @@ -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",
Expand Down Expand Up @@ -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:
Expand All @@ -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()));
}
Expand Down Expand Up @@ -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()));
}
Expand Down Expand Up @@ -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));
Expand Down Expand Up @@ -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) {
Expand Down
Loading