diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java index 8664d17d..36c4f38d 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java @@ -152,8 +152,9 @@ else if (s.contains(" - else if (s.contains("][gc")) { + // ...][info][gc ] + // or ...][info][safepoint ] Using java unified jvm logging format + else if (s.contains("][gc") || s.contains("][safepoint")) { if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Oracle / OpenJDK unified jvm logging"); return new DataReaderUnifiedJvmLogging(gcResource, in); } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java index e28ae7c0..8cddca04 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java @@ -14,6 +14,7 @@ import com.tagtraum.perf.gcviewer.model.AbstractGCEvent; 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; @@ -21,6 +22,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; @@ -157,9 +159,10 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader { private static final String TAG_GC_HEAP = "gc,heap"; private static final String TAG_GC_METASPACE = "gc,metaspace"; private static final String TAG_GC_PHASES = "gc,phases"; + private static final String TAG_SAFEPOINT = "safepoint"; /** list of strings, that must be part of the gc log line to be considered for parsing */ - private static final List INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES); + private static final List INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES, Type.APPLICATION_STOPPED_TIME.getName()); /** list of strings, that target gc log lines, that - although part of INCLUDE_STRINGS - are not considered a gc event */ private static final List EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", @@ -228,6 +231,9 @@ private ParseContext parseEvent(ParseContext context) { private AbstractGCEvent handleTail(ParseContext context, AbstractGCEvent event, String tags, String tail) { AbstractGCEvent returnEvent = event; switch (tags) { + case TAG_SAFEPOINT: + returnEvent = handleTagSafepoint(context, event, tail); + break; case TAG_GC_START: returnEvent = handleTagGcStartTail(context, event); break; @@ -254,6 +260,11 @@ private AbstractGCEvent handleTail(ParseContext context, AbstractGCEvent e return returnEvent; } + private AbstractGCEvent handleTagSafepoint(ParseContext context, AbstractGCEvent event, String tail) { + event.setPause(NumberParser.parseDouble(tail.split(" ")[0])); + return event; + } + private AbstractGCEvent handleTagGcStartTail(ParseContext context, AbstractGCEvent event) { // here, the gc type is known, and the partial events will need to be added later context.getPartialEventsMap().put(event.getNumber() + "", event); @@ -459,7 +470,7 @@ private AbstractGCEvent createGcEventWithStandardDecorators(Matcher decorator if (decoratorsMatcher.find()) { AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE)); - AbstractGCEvent event = type.getConcurrency().equals(Concurrency.CONCURRENT) ? new ConcurrentGCEvent() : new GCEventUJL(); + AbstractGCEvent event = createGcEvent(type); event.setExtendedType(type); if (decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER) != null) { event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER))); @@ -473,6 +484,18 @@ private AbstractGCEvent createGcEventWithStandardDecorators(Matcher decorator } } + private AbstractGCEvent createGcEvent(ExtendedType type) { + AbstractGCEvent event; + if (type.getConcurrency().equals(Concurrency.CONCURRENT)) { + event = new ConcurrentGCEvent(); + } else if (type.getType().equals(Type.APPLICATION_STOPPED_TIME)) { + event = new VmOperationEvent(); + } else { + event = new GCEventUJL(); + } + return event; + } + private void setPause(AbstractGCEvent event, String pauseAsString) { // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools if (pauseAsString != null && pauseAsString.length() > 0) { 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 ff9a0ce3..64802709 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java @@ -667,7 +667,7 @@ public String toString() { public static final Type UJL_G1_EDEN = new Type("Eden regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION); public static final Type UJL_G1_SURVIVOR = new Type("Survivor regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION); public static final Type UJL_G1_OLD = new Type("Old regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION); - public static final Type UJL_G1_HUMongous = new Type("Humongous regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION); + public static final Type UJL_G1_HUMONGOUS = new Type("Humongous regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION); public static final Type UJL_G1_ARCHIVE = new Type("Archive regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION); public static final Type UJL_G1_PHASE_PRE_EVACUATE_COLLECTION_SET = new Type("Pre Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_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 9ea33971..cb44688a 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderFactory.java @@ -373,4 +373,12 @@ public void testOracleShenandoahJ8Simple() throws Exception { assertDataReader(DataReaderSun1_6_0.class, dr.getClass()); } + @Test + public void testOpenJdkJulRollover() throws IOException { + DataReaderFactory factory = new DataReaderFactory(); + DataReader dr = factory.getDataReader(new GcResourceFile("byteArray"), new ByteArrayInputStream(( + "[2019-09-17T20:20:29.824+0000][19.163s][info ][safepoint ] Total time for which application threads were stopped: 0.0047914 seconds, Stopping threads took: 0.0000103 seconds\n\n").getBytes())); + assertDataReader(DataReaderUnifiedJvmLogging.class, dr.getClass()); + } + } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java index 31138213..221b3195 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java @@ -91,12 +91,13 @@ public void parseGcDefaults() throws Exception { @Test public void parseGcAllSafepointOsCpu() throws Exception { GCModel model = getGCModelFromLogFile("sample-ujl-cms-gc-all,safepoint,os+cpu.txt"); - assertThat("size", model.size(), is(26)); + assertThat("size", model.size(), is(37)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(3)); + assertThat("amount of VM operation pause types", model.getVmOperationPause().getN(), is(11)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(4)); - AbstractGCEvent event1 = model.get(0); + AbstractGCEvent event1 = model.get(1); UnittestHelper.testMemoryPauseEvent(event1, "young", Type.UJL_PAUSE_YOUNG, @@ -106,7 +107,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { false); // GC(3) Pause Initial Mark - AbstractGCEvent event2 = model.get(3); + AbstractGCEvent event2 = model.get(7); UnittestHelper.testMemoryPauseEvent(event2, "initial mark", Type.UJL_PAUSE_INITIAL_MARK, @@ -117,7 +118,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { assertThat("isInitialMark", event2.isInitialMark(), is(true)); // GC(3) Pause Remark - AbstractGCEvent remarkEvent = model.get(10); + AbstractGCEvent remarkEvent = model.get(15); UnittestHelper.testMemoryPauseEvent(remarkEvent, "remark", Type.UJL_PAUSE_REMARK, @@ -128,7 +129,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { assertThat("isRemark", remarkEvent.isRemark(), is(true)); // GC(5) Pause Full - AbstractGCEvent fullGcEvent = model.get(13); + AbstractGCEvent fullGcEvent = model.get(19); UnittestHelper.testMemoryPauseEvent(fullGcEvent, "full gc ", Type.UJL_PAUSE_FULL, @@ -137,10 +138,10 @@ public void parseGcAllSafepointOsCpu() throws Exception { Generation.ALL, true); - AbstractGCEvent concurrentMarkBeginEvent = model.get(4); + AbstractGCEvent concurrentMarkBeginEvent = model.get(9); assertThat("event is not start of concurrent collection", concurrentMarkBeginEvent.isConcurrentCollectionStart(), is(false)); - AbstractGCEvent concurrentMarkWithPauseEvent = model.get(5); + AbstractGCEvent concurrentMarkWithPauseEvent = model.get(10); assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true)); } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java index e9b0d084..a1b2754e 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java @@ -108,14 +108,15 @@ public void parseGcDefaults() throws Exception { @Test public void parseGcAllSafepointOsCpu() throws Exception { GCModel model = getGCModelFromLogFile("sample-ujl-g1-gc-all,safepoint,os+cpu.txt"); - assertThat("size", model.size(), is(15)); + assertThat("size", model.size(), is(29)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(4)); assertThat("amount of STW GC pauses", model.getGCPause().getN(), is(13)); + assertThat("amount of VM operation pauses", model.getVmOperationPause().getN(), is(14)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(0)); assertThat("amount of STW Full GC pauses", model.getFullGCPause().getN(), is(0)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(1)); - AbstractGCEvent event1 = model.get(0); + AbstractGCEvent event1 = model.get(1); UnittestHelper.testMemoryPauseEvent(event1, "young", Type.UJL_PAUSE_YOUNG, @@ -125,8 +126,8 @@ public void parseGcAllSafepointOsCpu() throws Exception { false); assertThat("young heap before", event1.details().next().getPreUsed(), is(1024 * 14)); - // GC(3) Pause Initial Mark - AbstractGCEvent event2 = model.get(5); + // GC(6) Pause Initial Mark + AbstractGCEvent event2 = model.get(11); UnittestHelper.testMemoryPauseEvent(event2, "initial mark", Type.UJL_PAUSE_INITIAL_MARK, @@ -136,8 +137,8 @@ public void parseGcAllSafepointOsCpu() throws Exception { false); assertThat("isInitialMark", event2.isInitialMark(), is(true)); - // GC(3) Pause Remark - AbstractGCEvent remarkEvent = model.get(10); + // GC(6) Pause Remark + AbstractGCEvent remarkEvent = model.get(20); UnittestHelper.testMemoryPauseEvent(remarkEvent, "remark", Type.UJL_PAUSE_REMARK, @@ -147,7 +148,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { false); assertThat("isRemark", remarkEvent.isRemark(), is(true)); - AbstractGCEvent cleanupEvent = model.get(13); + AbstractGCEvent cleanupEvent = model.get(26); UnittestHelper.testMemoryPauseEvent(cleanupEvent, "cleanup", Type.UJL_G1_PAUSE_CLEANUP, @@ -156,12 +157,14 @@ public void parseGcAllSafepointOsCpu() throws Exception { Generation.TENURED, false); - AbstractGCEvent concurrentCycleBeginEvent = model.get(6); + AbstractGCEvent concurrentCycleBeginEvent = model.get(13); + assertThat("concurrent cycle", concurrentCycleBeginEvent.getTypeAsString(), is(Type.UJL_G1_CONCURRENT_CYCLE.getName())); assertThat("event is start of concurrent collection", concurrentCycleBeginEvent.isConcurrentCollectionStart(), is(true)); - AbstractGCEvent concurrentCycleEndEvent = model.get(14); + AbstractGCEvent concurrentCycleEndEvent = model.get(28); + assertThat("concurrent cycle", concurrentCycleEndEvent.getTypeAsString(), is(Type.UJL_G1_CONCURRENT_CYCLE.getName())); assertThat("event is end of concurrent collection", concurrentCycleEndEvent.isConcurrentCollectionEnd(), is(true)); @@ -170,7 +173,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { @Test public void parseGcAllSafepointOsCpuWithToSpaceExhausted() throws Exception { GCModel model = getGCModelFromLogFile("sample-ujl-g1-gc-all,safepoint,os+cpu-to-space-exhausted.txt"); - assertThat("size", model.size(), is(1)); + assertThat("size", model.size(), is(2)); AbstractGCEvent youngEvent = model.get(0); UnittestHelper.testMemoryPauseEvent(youngEvent, "young", diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java index 0e0214aa..022712f0 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java @@ -146,7 +146,7 @@ public void testFullGcWithPhases() throws Exception { GCModel model = reader.read(); assertThat("number of warnings", handler.getCount(), is(0)); - assertThat("number of events", model.size(), is(1)); + assertThat("number of events", model.size(), is(2)); assertThat("total heap", model.get(0).getTotal(), is(128 * 1024)); } @@ -180,4 +180,23 @@ public void testPauseYoungConcurrentStartMetadataGcThreshold() throws Exception assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_PAUSE_YOUNG)); assertThat("total heap", model.get(0).getTotal(), is(256 * 1024)); } + + @Test + public void testTotalTimeForWhichApplicationThreadsWereStopped() throws IOException { + TestLogHandler handler = new TestLogHandler(); + handler.setLevel(Level.WARNING); + GCResource gcResource = new GcResourceFile("byteArray"); + gcResource.getLogger().addHandler(handler); + InputStream in = new ByteArrayInputStream( + ("[2019-09-17T20:20:29.824+0000][19.163s][info ][safepoint ] Total time for which application threads were stopped: 0.0047914 seconds, Stopping threads took: 0.0000103 seconds\n\n") + .getBytes()); + + DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in); + GCModel model = reader.read(); + + assertThat("number of warnings", handler.getCount(), is(0)); + assertThat("number of events", model.size(), is(1)); + assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.APPLICATION_STOPPED_TIME)); + assertThat("total heap", model.get(0).getPause(), closeTo(0.0047914, 0.0000001)); + } } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java index 1100b678..0060d525 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java @@ -59,7 +59,7 @@ public void parseGcDefaults() throws Exception { @Test public void parseGcAllSafepointOsCpu() throws Exception { GCModel model = getGCModelFromLogFile("sample-ujl-parallel-gc-all,safepoint,os+cpu.txt"); - assertThat("size", model.size(), is(8)); + assertThat("size", model.size(), is(14)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(1)); assertThat("amount of gc events", model.getGCPause().getN(), is(4)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1)); @@ -68,7 +68,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { assertThat("amount of events for phase 1 types", model.getGcEventPhases().get(Type.UJL_PARALLEL_PHASE_MARKING.getName()).getN(), is(4)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0)); - AbstractGCEvent event1 = model.get(0); + AbstractGCEvent event1 = model.get(1); UnittestHelper.testMemoryPauseEvent(event1, "pause young", Type.UJL_PAUSE_YOUNG, @@ -78,7 +78,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { false); // GC(6) Pause Full (Ergonomics) - AbstractGCEvent event2 = model.get(6); + AbstractGCEvent event2 = model.get(11); UnittestHelper.testMemoryPauseEvent(event2, "pause full", Type.UJL_PAUSE_FULL, @@ -88,7 +88,7 @@ public void parseGcAllSafepointOsCpu() throws Exception { true); // GC(7) Pause Young (Allocation Failure) - AbstractGCEvent event3 = model.get(7); + AbstractGCEvent event3 = model.get(13); UnittestHelper.testMemoryPauseEvent(event3, "pause young 2", Type.UJL_PAUSE_YOUNG, diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java index 709d1737..633c5140 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java @@ -65,14 +65,15 @@ public void parseGcDefaults() throws Exception { @Test public void parseGcAllSafepointOsCpu() throws Exception { GCModel model = getGCModelFromLogFile("sample-ujl-serial-gc-all,safepoint,os+cpu.txt"); - assertThat("size", model.size(), is(4)); + assertThat("size", model.size(), is(8)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(1)); assertThat("amount of STW GC pauses", model.getGCPause().getN(), is(3)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1)); assertThat("amount of STW Full GC pauses", model.getFullGCPause().getN(), is(1)); + assertThat("amount of vm operation events", model.getVmOperationPause().getN(), is(4)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0)); - AbstractGCEvent event1 = model.get(0); + AbstractGCEvent event1 = model.get(1); assertThat("event1 type", event1.getTypeAsString(), startsWith(Type.UJL_PAUSE_YOUNG.getName())); assertThat("event1 pause", event1.getPause(), closeTo(0.009814, 0.00001)); assertThat("event1 heap before", event1.getPreUsed(), is(1024 * 25)); @@ -81,16 +82,16 @@ public void parseGcAllSafepointOsCpu() throws Exception { // TODO fix timestamps or renderers (seeing the ujl logs, I realise, that the timestamps usually are the end of the event, not the beginning, as I kept thinking) // GC(3) Pause Full (Allocation Failure) - AbstractGCEvent event2 = model.get(2); - assertThat("event2 type", event2.getTypeAsString(), startsWith(Type.UJL_PAUSE_FULL.getName())); - assertThat("event2 pause", event2.getPause(), closeTo(0.006987, 0.00001)); - assertThat("event2 time", event2.getTimestamp(), closeTo(0.290, 0.0001)); + AbstractGCEvent event5 = model.get(5); + assertThat("event5 type", event5.getTypeAsString(), startsWith(Type.UJL_PAUSE_FULL.getName())); + assertThat("event5 pause", event5.getPause(), closeTo(0.006987, 0.00001)); + assertThat("event5 time", event5.getTimestamp(), closeTo(0.290, 0.0001)); // GC(2) Pause Young (Allocation Failure) - AbstractGCEvent event3 = model.get(3); - assertThat("event3 type", event3.getTypeAsString(), startsWith(Type.UJL_PAUSE_YOUNG.getName())); - assertThat("event3 pause", event3.getPause(), closeTo(0.007118, 0.00001)); - assertThat("event3 time", event3.getTimestamp(), closeTo(0.290, 0.0001)); + AbstractGCEvent event6 = model.get(6); + assertThat("event6 type", event6.getTypeAsString(), startsWith(Type.UJL_PAUSE_YOUNG.getName())); + assertThat("event6 pause", event6.getPause(), closeTo(0.007118, 0.00001)); + assertThat("event6 time", event6.getTimestamp(), closeTo(0.290, 0.0001)); } @Test diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java index 748875ad..a54d92a2 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java @@ -53,8 +53,9 @@ public void parseAllocationFailure() throws Exception { @Test public void parsePassiveHeuristics() throws Exception { GCModel model = getGCModelFromLogFile("SampleShenandoahPassiveHeuristics.txt"); - assertThat("size", model.size(), is(0)); + assertThat("size", model.size(), is(3)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(0)); + assertThat("amount of VM operation pause types", model.getVmOperationPause().getN(), is(3)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(0)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0)); } @@ -64,8 +65,9 @@ public void parsePassiveHeuristics() throws Exception { public void parseSingleSystemGCEvent() throws Exception { // this kind of system.gc event logging might have been removed in jdk1.8_232 GCModel model = getGCModelFromLogFile("SampleShenandoahSingleSystemGC.txt"); - assertThat("size", model.size(), is(1)); + assertThat("size", model.size(), is(2)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(0)); + assertThat("amount of VM operation pause types", model.getVmOperationPause().getN(), is(1)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0)); @@ -82,12 +84,12 @@ public void parseSingleSystemGCEvent() throws Exception { @Test public void parseSeveralSystemGCEvents() throws Exception { GCModel model = getGCModelFromLogFile("SampleShenandoahSeveralSystemGC.txt"); - assertThat("size", model.size(), is(438)); + assertThat("size", model.size(), is(878)); assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(0)); assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1)); assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0)); - GCEvent event = (GCEvent) model.get(0); + GCEvent event = (GCEvent) model.get(1); assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())")); assertThat("is system gc", event.isSystem(), is(true)); assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024)); @@ -101,7 +103,7 @@ public void parseSeveralSystemGCEvents() throws Exception { public void parseJdk11Beginning() throws Exception { // the main purpose if this test is to make sure, that no warnings are printed, when parsing the beginning of a shenandoah gc log file GCModel model = getGCModelFromLogFile("Sample-ujl-shenandoah-jdk11-beginning.txt"); - assertThat("size", model.size(), is(1)); + assertThat("size", model.size(), is(6)); } @Test @@ -151,7 +153,7 @@ public void testPauseInitMark() throws Exception { GCModel model = reader.read(); assertThat("number of warnings", handler.getCount(), is(0)); - assertThat("number of events", model.size(), is(1)); + assertThat("number of events", model.size(), is(2)); assertThat("event type as string", model.get(0).getTypeAsString(), is("Pause Init Mark (process weakrefs)")); assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_SHEN_INIT_MARK)); assertThat("event pause", model.get(0).getPause(), closeTo(0.001275, 0.0000001)); @@ -232,7 +234,7 @@ public void testPauseFinalMark() throws Exception { GCModel model = reader.read(); assertThat("number of warnings", handler.getCount(), is(0)); - assertThat("number of events", model.size(), is(1)); + assertThat("number of events", model.size(), is(2)); assertThat("event type", model.get(0).getTypeAsString(), is("Pause Final Mark (process weakrefs)")); assertThat("event pause", model.get(0).getPause(), closeTo(0.001404, 0.0000001)); assertThat("event preUsed", model.get(0).getPreUsed(), is(0)); @@ -308,7 +310,7 @@ public void testPauseInitUpdateRefs() throws Exception { GCModel model = reader.read(); assertThat("number of warnings", handler.getCount(), is(0)); - assertThat("number of events", model.size(), is(1)); + assertThat("number of events", model.size(), is(2)); assertThat("event type", model.get(0).getTypeAsString(), is("Pause Init Update Refs")); assertThat("event pause", model.get(0).getPause(), closeTo(0.000027, 0.0000001)); assertThat("event preUsed", model.get(0).getPreUsed(), is(0)); @@ -357,7 +359,7 @@ public void testPauseFinalUpdateRefs() throws Exception { GCModel model = reader.read(); assertThat("number of warnings", handler.getCount(), is(0)); - assertThat("number of events", model.size(), is(1)); + assertThat("number of events", model.size(), is(2)); assertThat("event type", model.get(0).getTypeAsString(), is("Pause Final Update Refs")); assertThat("event pause", model.get(0).getPause(), closeTo(0.000203, 0.0000001)); assertThat("event preUsed", model.get(0).getPreUsed(), is(0)); @@ -392,7 +394,7 @@ public void testConcurrentUncommit() throws Exception { public void testPauseDegeneratedGc() throws Exception { GCModel model = getGCModelFromLogFile("Sample-ujl-shenandoah-jdk11-PauseDegeneratedGc.txt"); - assertThat("number of events", model.size(), is(1)); + assertThat("number of events", model.size(), is(2)); assertThat("event type", model.get(0).getTypeAsString(), is("Pause Degenerated GC (Outside of Cycle)")); assertThat("event pause", model.get(0).getPause(), closeTo(0.011373, 0.0000001)); assertThat("event preUsed", model.get(0).getPreUsed(), is(119 * 1024));