@@ -27,6 +36,7 @@ *
@@ -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"; @@ -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:" @@ -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) { diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java index a43abc64..a197aa22 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java @@ -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); diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java index d1c13490..a0950874 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java @@ -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()); + } + } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java index 95161823..b0176a70 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java @@ -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; @@ -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)); + } }