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

Added application stopped events to JDK unified logging parser #208

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

Added application stopped events to JDK unified logging parser #208

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
3560b3e
initial refactoring, using to stage pass, first we extract log event …
kcrimson Oct 26, 2018
2eab1e8
minor refactoring, code should be more readable now
kcrimson Oct 29, 2018
772c33a
fixed code style issues
kcrimson Oct 29, 2018
0e2834b
initial refactoring, using to stage pass, first we extract log event …
kcrimson Oct 26, 2018
facaa58
minor refactoring, code should be more readable now
kcrimson Oct 29, 2018
38db187
fixed code style issues
kcrimson Oct 29, 2018
e06b5e6
Merge branch 'application_stopped_unified_logging' of github.com:kcri…
kcrimson Feb 18, 2019
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
117 changes: 91 additions & 26 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 @@ -21,6 +21,7 @@
import com.tagtraum.perf.gcviewer.model.GCEventUJL;
import com.tagtraum.perf.gcviewer.model.GCModel;
import com.tagtraum.perf.gcviewer.model.GCResource;
import com.tagtraum.perf.gcviewer.model.VmOperationEvent;
import com.tagtraum.perf.gcviewer.util.DateHelper;
import com.tagtraum.perf.gcviewer.util.NumberParser;

Expand Down Expand Up @@ -57,13 +58,21 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
// 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}.*))|$)
// 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
private static final Pattern PATTERN_DECORATORS = Pattern.compile(
"^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
);

// matches log decorators (like time stamp, up time, level, tags and message)
private static final Pattern PATTERN_DECORATORS = Pattern.compile("^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](?<message>.*)");

// matches gc event
private static final Pattern PATTERN_GC_MESSAGE = Pattern.compile("^GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)");

// matches application stopped time (entries with [safepoint] tag
private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds");

private static final String GROUP_DECORATORS_TIME = "time";
private static final String GROUP_DECORATORS_UPTIME = "uptime";
private static final String GROUP_DECORATORS_LEVEL = "level";
private static final String GROUP_DECORATORS_TAGS = "tags";
private static final String GROUP_DECORATORS_MESSAGE = "message";
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";
Expand Down Expand Up @@ -124,13 +133,14 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
private static final String TAG_GC_METASPACE = "gc,metaspace";

/** list of strings, that must be part of the gc log line to be considered for parsing */
private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[safepoint]","[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
/** list of strings, that target gc log lines, that - although part of INCLUDE_STRINGS - are not considered a gc event */
private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace", "gc,heap,coops", "gc,heap,exit");
private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace", "gc,heap,coops", "gc,heap,exit", "Application time:");
/** list of strings, that are gc log lines, but not a gc event -&gt; should be logged only */
private static final List<String> LOG_ONLY_STRINGS = Arrays.asList("Using", "Heap region size");



protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
super(gcResource, in);
}
Expand Down Expand Up @@ -162,25 +172,60 @@ public GCModel read() throws IOException {

private ParseContext parseEvent(ParseContext context) {
AbstractGCEvent<?> event = null;

Matcher decoratorsMatcher = PATTERN_DECORATORS.matcher(context.getLine());
try {
event = createGcEventWithStandardDecorators(decoratorsMatcher, context.getLine());
if (event != null) {
String tags = decoratorsMatcher.group(GROUP_DECORATORS_TAGS);
String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
event = handleTail(context, event, tags, tail);
String line = context.getLine();

// extract log decorators (like time stamp, up time, level, tags and message)
Matcher eventDecoratorsMatcher = PATTERN_DECORATORS.matcher(line );
LogEvent logEvent = parseLogEvent(eventDecoratorsMatcher);

if (logEvent==null) {
getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
} else {
String message = logEvent.message;
try {
if("safepoint".equals(logEvent.tags)) {
Matcher applicationStoppedMatcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
event = parseSafepointEvent(logEvent, applicationStoppedMatcher);
} else {
Matcher gcMatcher = PATTERN_GC_MESSAGE.matcher(message);
event = createGcEvent(context, logEvent, gcMatcher);
}
} catch (UnknownGcTypeException | NumberFormatException e) {
// prevent incomplete event from being added to the GCModel
event = null;
getLogger().warning(String.format("Failed to parse gc event (%s) on line number %d (line=\"%s\")", e.toString(), in.getLineNumber(), context.getLine()));
}
} catch (UnknownGcTypeException | NumberFormatException e) {
// prevent incomplete event from being added to the GCModel
event = null;
getLogger().warning(String.format("Failed to parse gc event (%s) on line number %d (line=\"%s\")", e.toString(), in.getLineNumber(), context.getLine()));
}


context.setCurrentEvent(event);
return context;
}

private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher) {
if (applicationStoppedMatcher.find()) {
AbstractGCEvent<?> event = new VmOperationEvent();
event.setType(Type.APPLICATION_STOPPED_TIME);
setPause(event, applicationStoppedMatcher.group("applicationstopped"));
setDateStampIfPresent(event, logEvent.time);
setTimeStampIfPresent(event, logEvent.uptime);
return event;
}
return null;
}

private LogEvent parseLogEvent(Matcher eventDecoratorsMatcher) {
if(eventDecoratorsMatcher.matches()) {
String time = eventDecoratorsMatcher.group( GROUP_DECORATORS_TIME );
String uptime = eventDecoratorsMatcher.group( GROUP_DECORATORS_UPTIME );
String level = eventDecoratorsMatcher.group( GROUP_DECORATORS_LEVEL );
String tags = eventDecoratorsMatcher.group( GROUP_DECORATORS_TAGS );
String message = eventDecoratorsMatcher.group( GROUP_DECORATORS_MESSAGE );
return new LogEvent(time,uptime,level,tags,message);
}
return null;
}

private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> event, String tags, String tail) {
AbstractGCEvent<?> returnEvent = event;
switch (tags) {
Expand Down Expand Up @@ -321,27 +366,29 @@ private void parseGcRegionTail(ParseContext context, AbstractGCEvent<?> event, S
/**
* Returns an instance of AbstractGcEvent (GCEvent or ConcurrentGcEvent) with all decorators present filled in
* or <code>null</code> if the line could not be matched.
* @param logEvent
* @param decoratorsMatcher matcher for decorators to be used for GcEvent creation
* @param line current line to be parsed
* @return Instance of <code>AbstractGcEvent</code> or <code>null</code> if the line could not be matched.
*/
private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
if (decoratorsMatcher.find()) {
private AbstractGCEvent<?> createGcEvent(ParseContext context, LogEvent logEvent, Matcher decoratorsMatcher) throws UnknownGcTypeException {
if (decoratorsMatcher.matches()) {
AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE));

AbstractGCEvent<?> event = type.getConcurrency().equals(Concurrency.CONCURRENT) ? new ConcurrentGCEvent() : new GCEventUJL();
event.setExtendedType(type);
event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME));
setDateStampIfPresent(event, logEvent.time);
setTimeStampIfPresent(event, logEvent.uptime);
String tags = logEvent.tags;
String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
event = handleTail(context, event, tags, tail);
return event;
} else {
getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
return null;
}
return null;
}

private void setPause(AbstractGCEvent event, String pauseAsString) {
private void setPause(AbstractGCEvent<?> event, String pauseAsString) {
// TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
if (pauseAsString != null && pauseAsString.length() > 0) {
event.setPause(NumberParser.parseDouble(pauseAsString) / 1000);
Expand All @@ -352,7 +399,7 @@ private boolean hasMemory(AbstractGCEvent<?> event) {
return event.getTotal() > 0;
}

private void setMemory(AbstractGCEvent event, Matcher matcher) {
private void setMemory(AbstractGCEvent<?> event, Matcher matcher) {
// TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
event.setPreUsed(getDataReaderTools().getMemoryInKiloByte(
Integer.parseInt(matcher.group(GROUP_MEMORY_BEFORE)), matcher.group(GROUP_MEMORY_BEFORE_UNIT).charAt(0), matcher.group(GROUP_MEMORY)));
Expand Down Expand Up @@ -457,5 +504,23 @@ public String toString() {
}

}

class LogEvent {

private final String time;
private final String uptime;
private final String level;
private final String tags;
private final String message;

LogEvent(String time, String uptime, String level, String tags, String message) {
this.time = time;
this.uptime = uptime;
this.level = level;
this.tags = tags;
this.message = message;
}

}

}
51 changes: 51 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,51 @@
package com.tagtraum.perf.gcviewer.imp;

import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
import com.tagtraum.perf.gcviewer.model.GCModel;
import org.junit.Test;

import java.io.IOException;
import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;

import static org.hamcrest.Matchers.is;
import static org.junit.Assert.assertThat;

/**
* Tests unified jvm logging parser for safepoint events.
*/
public class TestDataReaderUJLSafepoint {

private GCModel getGCModelFromLogFile(String fileName) throws IOException {
return UnittestHelper.getGCModelFromLogFile(fileName, FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class);
}

@Test
public void parseGcDefaults() throws Exception {
GCModel model = getGCModelFromLogFile("sample-ujl-safepoint-defaults.txt");
assertThat("size", model.size(), is(46));
assertThat("amount of gc event types", model.getGcEventPauses().size(), is(1));
assertThat("amount of gc events", model.getGCPause().getN(), is(20));
assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(0));
assertThat("amount of full gc events", model.getFullGCPause().getN(), is(0));
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));

List<AbstractGCEvent<?>> vmOperationsEvents = toList(model.getVmOperationsEvents());
assertThat("amount of application stopped types", vmOperationsEvents.size(), is(26));


AbstractGCEvent<?> event = model.get(0);
assertThat(event.getTypeAsString(),is("Total time for which application threads were stopped"));
assertThat(event.getPause(),is(0.0000000235));
}

private static <T> List<T> toList(Iterator<T> iterator){
ArrayList<T> list = new ArrayList<>();
iterator.forEachRemaining(list::add);
return list;
}

}
Loading