Skip to content

Commit

Permalink
Merge branch 'feature/#198/shenandoah-non-unified-logging-format' int…
Browse files Browse the repository at this point in the history 
…o develop
  • Loading branch information
@chewiebug
chewiebug committed Jun 25, 2018
2 parents b363505 + a62a8af commit e8e26e9
Show file tree
Hide file tree
Showing 6 changed files with 176 additions and 53 deletions.
9 changes: 7 additions & 2 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -180,7 +180,7 @@ private boolean isNumberCharacter(char character) {
|| character == ','; // some localised log files contain "," instead of "." in numbers
}

protected void setMemory(GCEvent event, String line, ParseInformation pos) throws ParseException {
protected void setMemory(AbstractGCEvent<?> event, String line, ParseInformation pos) throws ParseException {
int start = skipUntilNextDigit(line, pos);
int end = line.indexOf("->", pos.getIndex()) - 1;
if (end != -2) for (start = end-1; start >= 0 && Character.isDigit(line.charAt(start)); start--) {}
Expand Down Expand Up @@ -226,7 +226,12 @@ protected double parsePause(String line, ParseInformation pos) throws ParseExcep
if (end < 0) {
end = line.indexOf(']', begin);
}
final double pause = NumberParser.parseDouble(line.substring(begin, end));
double pause = NumberParser.parseDouble(line.substring(begin, end));

// ms...
if (line.endsWith("ms]")) {
pause = pause / 1000;
}

// skip "secs]"
pos.setIndex(line.indexOf(']', end) + 1);
Expand Down
2 changes: 1 addition & 1 deletion src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -164,7 +164,7 @@ else if (s.contains(" (young)") || s.contains("G1Ergonomics") || s.contains(" (m
if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Sun 1.6.x G1 collector");
return new DataReaderSun1_6_0G1(gcResource, in, GcLogType.SUN1_6G1);
}
else if (s.contains("[Times:")) {
else if (s.contains("[Times:") || s.contains("[Pause Init Mark") /* Shenandoah, -XX:-PrintGCDetails */) {
// all 1.6 lines end with a block like this "[Times: user=1.13 sys=0.08, real=0.95 secs]"
if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Sun 1.6.x");
return new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_6);
Expand Down
100 changes: 50 additions & 50 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java
View file
Original file line number Diff line number Diff line change
@@ -1,10 +1,5 @@
package com.tagtraum.perf.gcviewer.imp;

import com.tagtraum.perf.gcviewer.model.*;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.*;
import com.tagtraum.perf.gcviewer.util.NumberParser;
import com.tagtraum.perf.gcviewer.util.ParseInformation;

import java.io.IOException;
import java.io.InputStream;
import java.io.LineNumberReader;
Expand All @@ -17,6 +12,20 @@
import java.util.regex.Matcher;
import java.util.regex.Pattern;

import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.CollectionType;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Concurrency;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.GcPattern;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
import com.tagtraum.perf.gcviewer.model.ConcurrentGCEvent;
import com.tagtraum.perf.gcviewer.model.GCEvent;
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.NumberParser;
import com.tagtraum.perf.gcviewer.util.ParseInformation;

/**
* Parses log output from Sun / Oracle Java 1.4 / 1.5 / 1.6. / 1.7 / 1.8.
* <p>
Expand All @@ -27,6 +36,7 @@
* <li>-XX:+UseParNewGC</li>
* <li>-XX:+UseParallelOldGC</li>
* <li>-XX:+UseConcMarkSweepGC</li>
* <li>-XX:+UseShenandoahGC</li>
* <li>-Xincgc (1.4 / 1.5)</li>
* </ul>
* <p>
Expand Down Expand Up @@ -102,6 +112,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
EXCLUDE_STRINGS.add("PS" + ADAPTIVE_PATTERN); // -XX:PrintAdaptiveSizePolicy
EXCLUDE_STRINGS.add(" avg_survived_padded_avg"); // -XX:PrintAdaptiveSizePolicy
EXCLUDE_STRINGS.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
EXCLUDE_STRINGS.add("Uncommitted"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC
}

private static final String EVENT_YG_OCCUPANCY = "YG occupancy";
Expand Down Expand Up @@ -538,7 +550,6 @@ private boolean isCmsScavengeBeforeRemark(String line) {
}

protected AbstractGCEvent<?> parseLine(String line, ParseInformation pos) throws ParseException {
AbstractGCEvent<?> ae = null;
try {
// parse datestamp "yyyy-MM-dd'T'hh:mm:ssZ:"
// parse timestamp "double:"
Expand All @@ -548,57 +559,46 @@ protected AbstractGCEvent<?> parseLine(String line, ParseInformation pos) throws
ZonedDateTime datestamp = parseDatestamp(line, pos);
double timestamp = getTimestamp(line, pos, datestamp);
ExtendedType type = parseType(line, pos);
// special provision for CMS events
AbstractGCEvent<?> ae;
if (type.getConcurrency() == Concurrency.CONCURRENT) {
ae = new ConcurrentGCEvent();
ConcurrentGCEvent event = (ConcurrentGCEvent)ae;

// simple concurrent events (ending with -start) just are of type GcPattern.GC
event.setDateStamp(datestamp);
event.setTimestamp(timestamp);
event.setExtendedType(type);
if (type.getPattern() == GcPattern.GC_PAUSE_DURATION) {
// the -end events contain a pause and duration as well
int start = pos.getIndex();
int end = line.indexOf('/', pos.getIndex());
event.setPause(NumberParser.parseDouble(line.substring(start, end)));
start = end + 1;
end = line.indexOf(' ', start);
event.setDuration(NumberParser.parseDouble(line.substring(start, end)));
}
// nothing more to parse...
}
else if (type.getCollectionType().equals(CollectionType.VM_OPERATION)) {
} else if (type.getCollectionType().equals(CollectionType.VM_OPERATION)) {
ae = new VmOperationEvent();
VmOperationEvent vmOpEvent = (VmOperationEvent) ae;

vmOpEvent.setDateStamp(datestamp);
vmOpEvent.setTimestamp(timestamp);
vmOpEvent.setExtendedType(type);
vmOpEvent.setPause(parsePause(line, pos));
}
else {
} else {
ae = new GCEvent();
GCEvent event = (GCEvent) ae;

event.setDateStamp(datestamp);
event.setTimestamp(timestamp);
event.setExtendedType(type);
// now add detail gcevents, should they exist
parseDetailEventsIfExist(line, pos, event);
if (event.getExtendedType().getPattern() == GcPattern.GC_MEMORY_PAUSE
|| event.getExtendedType().getPattern() == GcPattern.GC_MEMORY) {
}

setMemory(event, line, pos);
}
// then more detail events follow (perm gen is usually here)
parseDetailEventsIfExist(line, pos, event);
if (event.getExtendedType().getPattern() == GcPattern.GC_MEMORY_PAUSE
|| event.getExtendedType().getPattern() == GcPattern.GC_PAUSE) {
ae.setDateStamp(datestamp);
ae.setTimestamp(timestamp);
ae.setExtendedType(type);
// now add detail gcevents, should they exist
if (ae instanceof GCEvent) {
parseDetailEventsIfExist(line, pos, (GCEvent) ae);
}
if (type.getPattern() == GcPattern.GC_MEMORY_PAUSE
|| type.getPattern() == GcPattern.GC_MEMORY) {

event.setPause(parsePause(line, pos));
}
setMemory(ae, line, pos);
}
// then more detail events follow (perm gen is usually here)
if (ae instanceof GCEvent) {
parseDetailEventsIfExist(line, pos, (GCEvent)ae);
}
if (type.getPattern() == GcPattern.GC_MEMORY_PAUSE
|| type.getPattern() == GcPattern.GC_PAUSE) {

ae.setPause(parsePause(line, pos));
} else if (type.getPattern() == GcPattern.GC_PAUSE_DURATION) {
// special case only occurring with concurrent collections...
// the -end events contain a pause and duration as well
int start = pos.getIndex();
int end = line.indexOf('/', pos.getIndex());
ae.setPause(NumberParser.parseDouble(line.substring(start, end)));
start = end + 1;
end = line.indexOf(' ', start);
((ConcurrentGCEvent) ae).setDuration(NumberParser.parseDouble(line.substring(start, end)));
}

return ae;
}
catch (RuntimeException rte) {
Expand Down
1 change: 1 addition & 0 deletions src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -642,6 +642,7 @@ public String toString() {
public static final Type UJL_SHEN_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_MARK = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_EVAC = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CANCEL_CONC_MARK = new Type("Cancel concurrent mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
Expand Down
11 changes: 11 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -323,4 +323,15 @@ public void testOracleG1J8() throws Exception {
assertDataReader(DataReaderSun1_6_0G1.class, dr.getClass());
}

@Test
public void testOracleShenandoahJ8Simple() throws Exception {
DataReaderFactory factory = new DataReaderFactory();
DataReader dr = factory.getDataReader(new GcResourceFile("byteArray"), new ByteArrayInputStream((
"OpenJDK 64-Bit Server VM (25.161-b14) for linux-amd64 JRE (1.8.0_161-b14), built on Jan 9 2018 19:54:33 by \"mockbuild\" with gcc 4.8.5 20150623 (Red Hat 4.8.5-16)\n" +
"Memory: 4k page, physical 8002012k(4357532k free), swap 2097148k(1656904k free)\n" +
"CommandLine flags: -XX:HeapDumpPath=/work -XX:InitialHeapSize=2147483648 -XX:LogFile=/log/jvm.log -XX:+LogVMOutput -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseNUMA -XX:+UseShenandoahGC \n" +
"13.976: [Pause Init Mark, 3.587 ms]\n").getBytes()));
assertDataReader(DataReaderSun1_6_0.class, dr.getClass());
}

}
106 changes: 106 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,12 +6,14 @@
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertThat;

import java.io.ByteArrayInputStream;
import java.io.IOException;
import java.io.InputStream;
import java.util.logging.Level;

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 com.tagtraum.perf.gcviewer.model.GCResource;
import com.tagtraum.perf.gcviewer.model.GcResourceFile;
Expand Down Expand Up @@ -132,4 +134,108 @@ public void cmsPrintHeapBeforeFullGc() throws Exception {

assertEquals("number of errors", 0, handler.getCount());
}

@Test
public void shenandoahPauseMark() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);

ByteArrayInputStream in = new ByteArrayInputStream(
("13.976: [Pause Init Mark, 3.587 ms]" +
"\n13.992: [Pause Final Mark 1447M->684M(2048M), 2.279 ms]")
.getBytes());

DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
GCModel model = reader.read();

assertThat("gc count", model.size(), is(2));
assertThat("warnings", handler.getCount(), is(0));

AbstractGCEvent<?> initMarkEvent = model.get(0);
assertThat("Pause init mark: name", initMarkEvent.getTypeAsString(), equalTo("Pause Init Mark"));
assertThat("Pause init mark: duration", initMarkEvent.getPause(), closeTo(0.003587, 0.00001));

AbstractGCEvent<?> finalMarkEvent = model.get(1);
assertThat("Pause final mark: name", finalMarkEvent.getTypeAsString(), equalTo("Pause Final Mark"));
assertThat("Pause final mark: duration", finalMarkEvent.getPause(), closeTo(0.002279, 0.00001));
assertThat("Pause final mark: before", finalMarkEvent.getPreUsed(), is(1447 * 1024));
}

@Test
public void shenandoahPauseUpdateRefs() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);

ByteArrayInputStream in = new ByteArrayInputStream(
("14.001: [Pause Init Update Refs, 0.073 ms]" +
"\n14.016: [Pause Final Update Refs 726M->60M(2048M), 0.899 ms]")
.getBytes());

DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
GCModel model = reader.read();

assertThat("gc count", model.size(), is(2));
assertThat("warnings", handler.getCount(), is(0));

AbstractGCEvent<?> initUpdateRefsEvent = model.get(0);
assertThat("Pause init update refs: name", initUpdateRefsEvent.getTypeAsString(), equalTo("Pause Init Update Refs"));
assertThat("Pause init update refs: duration", initUpdateRefsEvent.getPause(), closeTo(0.000073, 0.0000001));

AbstractGCEvent<?> finalUpdateRefsEvent = model.get(1);
assertThat("Pause Final Update Refs: name", finalUpdateRefsEvent.getTypeAsString(), equalTo("Pause Final Update Refs"));
assertThat("Pause Final Update Refs: duration", finalUpdateRefsEvent.getPause(), closeTo(0.000899, 0.00001));
assertThat("Pause Final Update Refs: before", finalUpdateRefsEvent.getPreUsed(), is(726 * 1024));
}

@Test
public void shehandoahConcurrentEvents() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);

ByteArrayInputStream in = new ByteArrayInputStream(
("13.979: [Concurrent marking 1435M->1447M(2048M), 12.576 ms]" +
"\n13.994: [Concurrent evacuation 684M->712M(2048M), 6.041 ms]" +
"\n14.001: [Concurrent update references 713M->726M(2048M), 14.718 ms]" +
"\n14.017: [Concurrent reset bitmaps 60M->62M(2048M), 0.294 ms]" +
"\n626.259: [Cancel concurrent mark, 0.056 ms]\n")
.getBytes());

DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
GCModel model = reader.read();

assertThat("gc count", model.size(), is(5));
assertThat("warnings", handler.getCount(), is(0));

AbstractGCEvent<?> concurrentMarking = model.get(0);
assertThat("Concurrent Marking: name", concurrentMarking.getTypeAsString(), equalTo("Concurrent marking"));
assertThat("Concurrent Marking: duration", concurrentMarking.getPause(), closeTo(0.012576, 0.0000001));
assertThat("Concurrent Marking: before", concurrentMarking.getPreUsed(), is(1435 * 1024));
assertThat("Concurrent Marking: after", concurrentMarking.getPostUsed(), is(1447 * 1024));
assertThat("Concurrent Marking: total", concurrentMarking.getTotal(), is(2048 * 1024));
}

@Test
public void shenandoahIgnoredLines() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);

ByteArrayInputStream in = new ByteArrayInputStream(
("Uncommitted 87M. Heap: 2048M reserved, 1961M committed, 992M used" +
"\nCancelling concurrent GC: Allocation Failure")
.getBytes());

DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
GCModel model = reader.read();

assertThat("gc count", model.size(), is(0));
assertThat("warnings", handler.getCount(), is(0));
}
}

0 comments on commit e8e26e9

Please sign in to comment.