diff --git a/api/src/main/java/com/microsoft/gctoolkit/event/g1gc/G1Young.java b/api/src/main/java/com/microsoft/gctoolkit/event/g1gc/G1Young.java index d47f2a46..a44d9e18 100644 --- a/api/src/main/java/com/microsoft/gctoolkit/event/g1gc/G1Young.java +++ b/api/src/main/java/com/microsoft/gctoolkit/event/g1gc/G1Young.java @@ -6,6 +6,7 @@ import com.microsoft.gctoolkit.event.GarbageCollectionTypes; import com.microsoft.gctoolkit.event.StatisticalSummary; import com.microsoft.gctoolkit.event.UnifiedStatisticalSummary; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.time.DateTimeStamp; import java.util.Iterator; @@ -36,6 +37,7 @@ public class G1Young extends G1RealPause { private StatisticalSummary workerTotal; private StatisticalSummary processedBuffersSummary; private boolean toSpaceExhausted = false; + private SurvivorRecord survivorRecord; private final Map parallelPhaseSummaries = new ConcurrentHashMap<>(); private final Map phaseDurations = new ConcurrentHashMap<>(); @@ -196,6 +198,14 @@ public void addWorkerActivity(String group, StatisticalSummary statisticalSummar workerTotal = statisticalSummary; } + public void add(SurvivorRecord record) { + this.survivorRecord = record; + } + + public SurvivorRecord getSurvivorRecord() { + return survivorRecord; + } + public StatisticalSummary getWorkerOther() { return this.workerOther; } diff --git a/api/src/main/java/com/microsoft/gctoolkit/event/generational/GenerationalGCPauseEvent.java b/api/src/main/java/com/microsoft/gctoolkit/event/generational/GenerationalGCPauseEvent.java index 46f6de1e..6569fb87 100644 --- a/api/src/main/java/com/microsoft/gctoolkit/event/generational/GenerationalGCPauseEvent.java +++ b/api/src/main/java/com/microsoft/gctoolkit/event/generational/GenerationalGCPauseEvent.java @@ -7,6 +7,7 @@ import com.microsoft.gctoolkit.event.GarbageCollectionTypes; import com.microsoft.gctoolkit.event.MemoryPoolSummary; import com.microsoft.gctoolkit.event.ReferenceGCSummary; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.time.DateTimeStamp; public abstract class GenerationalGCPauseEvent extends GenerationalGCEvent { @@ -23,6 +24,7 @@ public abstract class GenerationalGCPauseEvent extends GenerationalGCEvent { private double stringTableProcessingTime; private double symbolAndStringTableProcessingTime; private BinaryTreeDictionary binaryTreeDictionary; + private SurvivorRecord survivorRecord; private CPUSummary cpuSummary; @@ -114,6 +116,14 @@ public void addClassUnloadingAndStringTableProcessingDurations(double classUnloa this.symbolAndStringTableProcessingTime = symbolAndStringTable; } + public void add(SurvivorRecord record) { + this.survivorRecord = record; + } + + public SurvivorRecord getSurvivorRecord() { + return survivorRecord; + } + public double getClassUnloadingProcessingTime() { return this.classUnloadingProcessingTime; } diff --git a/api/src/main/java/com/microsoft/gctoolkit/event/jvm/SurvivorRecord.java b/api/src/main/java/com/microsoft/gctoolkit/event/jvm/SurvivorRecord.java index 18a946ae..cf9bb054 100644 --- a/api/src/main/java/com/microsoft/gctoolkit/event/jvm/SurvivorRecord.java +++ b/api/src/main/java/com/microsoft/gctoolkit/event/jvm/SurvivorRecord.java @@ -16,8 +16,8 @@ public class SurvivorRecord extends JVMEvent { private int maxTenuringThreshold; // JDK bug, we have now seen a max tenuring threshold of 32, even 64 - // Fold anything older than 15 back into the 15th slot - private ArrayList bytesAtAge = null; + // Fold anything older than maxTenuringThreshold back into the maxTenuringThreshold slot + private long[] bytesAtAge; public SurvivorRecord(DateTimeStamp timeStamp, long desiredOccupancy, int calculatedTenuringThreshold, int maxTenuringThreshold) { super(timeStamp, 0.0d); @@ -56,31 +56,30 @@ public int getMaxTenuringThreshold() { public long getBytesAtAge(int age) { if (this.bytesAtAge == null) return 0L; - return this.bytesAtAge.get(age); + return this.bytesAtAge[age]; } /* * There is a bug in the JVM that allows tenuring threshold to appear to be greater than 15. - * Fold anything greater than 15 into 15. - * + * Fold anything greater than maxTenuringThreshold into maxTenuringThreshold. */ public void add(int age, long bytes) { if (bytesAtAge == null) { - bytesAtAge = new ArrayList<>(); - bytesAtAge.add(0L); //throw away the first slow. + bytesAtAge = new long[maxTenuringThreshold+1]; + bytesAtAge[0] = 0L; //throw away the first slot. } if (age <= maxTenuringThreshold) { - bytesAtAge.add(bytes); + bytesAtAge[age] = bytes; } else { - bytesAtAge.set(maxTenuringThreshold, bytesAtAge.get(maxTenuringThreshold) + bytes); + bytesAtAge[maxTenuringThreshold] += bytes; } } - public Long[] getBytesAtEachAge() { + public long[] getBytesAtEachAge() { if (bytesAtAge == null) - return new Long[0]; - return bytesAtAge.toArray(new Long[0]); + return new long[0]; + return bytesAtAge; } } diff --git a/gclogs/pom.xml b/gclogs/pom.xml index 5af3300e..2328db25 100644 --- a/gclogs/pom.xml +++ b/gclogs/pom.xml @@ -17,7 +17,7 @@ pom - 1.0.10 + 1.0.12 diff --git a/parser/src/main/java/com/microsoft/gctoolkit/parser/ForwardReference.java b/parser/src/main/java/com/microsoft/gctoolkit/parser/ForwardReference.java index 27077bb9..3969d219 100644 --- a/parser/src/main/java/com/microsoft/gctoolkit/parser/ForwardReference.java +++ b/parser/src/main/java/com/microsoft/gctoolkit/parser/ForwardReference.java @@ -4,6 +4,7 @@ import com.microsoft.gctoolkit.event.CPUSummary; import com.microsoft.gctoolkit.event.GCCause; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.parser.jvm.Decorators; import com.microsoft.gctoolkit.time.DateTimeStamp; @@ -15,6 +16,7 @@ public class ForwardReference { private double duration = -1.0d; private GCCause gcCause = GCCause.UNKNOWN_GCCAUSE; private CPUSummary cpuSummary = null; + SurvivorRecord survivorRecord = null; ForwardReference(Decorators decorators, int id) { this.gcID = id; @@ -69,4 +71,17 @@ Decorators getDecorators() { return decorators; } + public void survivorRecord(SurvivorRecord survivorRecord) { + this.survivorRecord = survivorRecord; + } + + public void addAgeBreakout(int age, long volume) { + if (this.survivorRecord == null) + return; + this.survivorRecord.add(age, volume); + } + + public SurvivorRecord getSurvivorRecord() { + return this.survivorRecord; + } } diff --git a/parser/src/main/java/com/microsoft/gctoolkit/parser/G1GCForwardReference.java b/parser/src/main/java/com/microsoft/gctoolkit/parser/G1GCForwardReference.java index a91b08fb..d7d60ffb 100644 --- a/parser/src/main/java/com/microsoft/gctoolkit/parser/G1GCForwardReference.java +++ b/parser/src/main/java/com/microsoft/gctoolkit/parser/G1GCForwardReference.java @@ -782,6 +782,8 @@ private G1Young buildYoung(G1Young collection) { if (toSpaceExhausted) collection.toSpaceExhausted(); if (hasReferenceGCSummary()) collection.add(generateReferenceGCSummary()); + if (survivorRecord != null) + collection.add(survivorRecord); collection.addCPUSummary(getCPUSummary()); return collection; } diff --git a/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParser.java b/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParser.java index 9a75822e..1d12ec75 100644 --- a/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParser.java +++ b/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParser.java @@ -15,6 +15,7 @@ import com.microsoft.gctoolkit.event.g1gc.G1GCPauseEvent; import com.microsoft.gctoolkit.event.jvm.JVMEvent; import com.microsoft.gctoolkit.event.jvm.JVMTermination; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.jvm.Diary; import com.microsoft.gctoolkit.message.ChannelName; import com.microsoft.gctoolkit.message.JVMEventChannel; @@ -47,7 +48,7 @@ * - pause time if it is reported or can be calculated * todo: me */ -public class UnifiedG1GCParser extends UnifiedGCLogParser implements UnifiedG1GCPatterns { +public class UnifiedG1GCParser extends UnifiedGCLogParser implements UnifiedG1GCPatterns, TenuredPatterns { private static final Logger LOGGER = Logger.getLogger(UnifiedG1GCParser.class.getName()); @@ -154,6 +155,8 @@ public class UnifiedG1GCParser extends UnifiedGCLogParser implements UnifiedG1GC parseRules.put(REBUILD_FREELIST, this::noop); parseRules.put(NEW_CSET, this::noop); parseRules.put(RESIZE_TLAB, this::noop); + parseRules.put(TENURING_SUMMARY, this::tenuringSummary); + parseRules.put(TENURING_AGE_BREAKDOWN, this::tenuringAgeBreakout); } public UnifiedG1GCParser() { @@ -672,6 +675,25 @@ private void fullStringSymbolTable(GCLogTrace trace, String line) { // forwardReference.scrubStringSymbolTableDuration(trace.getMillisecondDurationInSeconds()); } + /** + * Capture logged tenuring summary data + * @param trace + * @param line + */ + private void tenuringSummary(GCLogTrace trace, String line) { + forwardReference.survivorRecord(new SurvivorRecord(getClock(), trace.getLongGroup(1), trace.getIntegerGroup(2), trace.getIntegerGroup(3))); + } + + /** + * Capture logged age table data + * @param trace + * @param line + */ + private void tenuringAgeBreakout(GCLogTrace trace, String line) { + notYetImplemented(trace,line); + forwardReference.addAgeBreakout(trace.getIntegerGroup(1), trace.getLongGroup(2)); + } + /** * records a concurrent phase of a concurrent cycle. After the event has been recorded, all other events * that occurred during the concurrent event will be recorded. @@ -726,8 +748,6 @@ private void jvmExit(GCLogTrace trace, String s) { } private boolean ignoreFrequentlySeenButUnwantedLines(String line) { - if (line.contains("Desired survivor size")) return true; - if (line.contains("Age table with threshold")) return true; if (line.contains("safepoint")) return true; if (line.contains(") Skipped phase ")) return true; if (line.contains(" Total Min: ")) return true; @@ -738,7 +758,7 @@ private boolean ignoreFrequentlySeenButUnwantedLines(String line) { if (line.contains(" StringTable Weak Min:")) return true; if (line.contains(" ResolvedMethodTable Weak Min:")) return true; if (line.contains(" JNI Weak Min:")) return true; - return line.contains(" - age "); + return false; } /** diff --git a/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalParser.java b/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalParser.java index 27d76881..5ddd788a 100644 --- a/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalParser.java +++ b/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalParser.java @@ -25,6 +25,7 @@ import com.microsoft.gctoolkit.event.generational.SystemGC; import com.microsoft.gctoolkit.event.generational.YoungGC; import com.microsoft.gctoolkit.event.jvm.JVMTermination; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.jvm.Diary; import com.microsoft.gctoolkit.message.ChannelName; import com.microsoft.gctoolkit.message.JVMEventChannel; @@ -63,7 +64,7 @@ * - from, to, configured * - pause time if it is reported or can be calculated */ -public class UnifiedGenerationalParser extends UnifiedGCLogParser implements UnifiedGenerationalPatterns { +public class UnifiedGenerationalParser extends UnifiedGCLogParser implements UnifiedGenerationalPatterns, TenuredPatterns { private static final Logger LOGGER = Logger.getLogger(UnifiedGenerationalParser.class.getName()); @@ -100,6 +101,8 @@ public class UnifiedGenerationalParser extends UnifiedGCLogParser implements Uni parseRules.put(JVM_EXIT, this::jvmExit); parseRules.put(END_OF_FILE, this::jvmExit); parseRules.put(METASPACE_DETAILED, this::metaSpaceDetails); + parseRules.put(TENURING_SUMMARY, this::tenuringSummary); + parseRules.put(TENURING_AGE_BREAKDOWN, this::tenuringAgeBreakout); } @@ -229,6 +232,26 @@ private void youngDetails(GCLogTrace trace, String line) { pauseEvent.setHeap(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(2)); } + /** + * Capture logged tenuring summary data + * @param trace + * @param line + */ + private void tenuringSummary(GCLogTrace trace, String line) { + if ( pauseEvent != null) + pauseEvent.survivorRecord(new SurvivorRecord(getClock(), trace.getLongGroup(1), trace.getIntegerGroup(2), trace.getIntegerGroup(3))); + } + + /** + * Capture logged age table data + * @param trace + * @param line + */ + private void tenuringAgeBreakout(GCLogTrace trace, String line) { + if (pauseEvent != null) + pauseEvent.addAgeBreakout(trace.getIntegerGroup(1), trace.getLongGroup(2)); + } + /** * If the concurrentCyclePauseEvent has not been recorded, something has gone wrong and it's likely * that it doesn't have a consistent state. The default action is to lose it. @@ -449,13 +472,14 @@ private GenerationalGCPauseEvent buildYoungEvent(GenerationalForwardReference fo youngCollection = new PSYoungGen(forwardReference.getStartTime(), forwardReference.getGCCause(), forwardReference.getDuration()); break; default: - LOGGER.warning(forwardReference.getGarbageCollectionType() + " not recognized"); + throw new IllegalStateException(forwardReference.getGarbageCollectionType() + " not recognized"); } fillOutMemoryPoolData(youngCollection, forwardReference); fillOutMetaspaceData(youngCollection, forwardReference); youngCollection.add(forwardReference.getCPUSummary()); - // add in reference processing + youngCollection.add(forwardReference.getSurvivorRecord()); + // todo: add in reference processing return youngCollection; } @@ -519,7 +543,7 @@ private GenerationalGCPauseEvent buildPauseEvent(GenerationalForwardReference fo return buildInitialMark(forwardReference); case Remark: return buildRemark(forwardReference); - case PSFull: //todo: + case PSFull: case FullGC: case Full: return buildFullGC(forwardReference); @@ -565,8 +589,7 @@ private boolean ignoreFrequentlySeenButUnwantedLines(String line) { if (line.contains("exit")) if (line.contains("used")) return true; if (line.contains("workers")) return true; - if (line.contains("Heap address")) return true; - return line.contains("Desired") || line.contains("Age table") || line.contains("- age "); + return line.contains("Heap address"); } @Override diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCUnifiedParserRulesTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCUnifiedParserRulesTest.java index 0e081dde..b3b1be50 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCUnifiedParserRulesTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCUnifiedParserRulesTest.java @@ -12,7 +12,7 @@ import static com.microsoft.gctoolkit.parser.CommonTestHelper.captureTest; import static org.junit.jupiter.api.Assertions.*; -public class G1GCUnifiedParserRulesTest implements UnifiedG1GCPatterns { +public class G1GCUnifiedParserRulesTest implements UnifiedG1GCPatterns, TenuredPatterns { /** * The rules are; @@ -152,7 +152,9 @@ private void evaluate(GCParseRule rule, String string, boolean dump) { WEAK_PROCESSING, CLEANUP__FINALIZE_CONC_MARK, CONCURRENT_UNDO_CYCLE_START, - CONCURRENT_UNDO_CYCLE_END // 70 + CONCURRENT_UNDO_CYCLE_END , // 70 + TENURING_SUMMARY, + TENURING_AGE_BREAKDOWN }; /* @@ -446,6 +448,12 @@ private void evaluate(GCParseRule rule, String string, boolean dump) { }, { // 70 "[155.836s][info ][gc ] GC(2457) Concurrent Undo Cycle 49.351ms", + }, + { // 71 + "[10.749s][debug][gc,age ] GC(0) Desired survivor size 1572864 bytes, new threshold 15 (max threshold 15)\n" + }, + { // 72 + "[10.754s][trace][gc,age ] GC(0) - age 1: 2579584 bytes, 2579584 total" } // Remaining lines which may not need to be parsed... diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserRulesTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserRulesTest.java index 54edf0eb..ce3146da 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserRulesTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserRulesTest.java @@ -9,7 +9,7 @@ import static com.microsoft.gctoolkit.parser.CommonTestHelper.captureTest; import static org.junit.jupiter.api.Assertions.*; -public class GenerationalHeapParserRulesTest implements SimplePatterns, SerialPatterns, ParallelPatterns, CMSPatterns, ICMSPatterns { +public class GenerationalHeapParserRulesTest implements SimplePatterns, SerialPatterns, ParallelPatterns, CMSPatterns, ICMSPatterns, TenuredPatterns { private static final Logger LOGGER = Logger.getLogger(GenerationalHeapParserRulesTest.class.getName()); @@ -250,7 +250,9 @@ private void evaluate(GCParseRule rule, String string, boolean dump) { // CMF_LARGE_BLOCK, // //this rule must be evaluated before CONCURRENT_PHASE_END_BLOCK // ABORT_PRECLEAN_DUE_TO_TIME_CLAUSE, - PRECLEAN_REFERENCE + PRECLEAN_REFERENCE, + TENURING_SUMMARY, + TENURING_AGE_BREAKDOWN }; private String[][] lines = { @@ -591,6 +593,12 @@ private void evaluate(GCParseRule rule, String string, boolean dump) { // }, { "2016-04-01T15:03:42.171-0700: 11025.637: [Preclean SoftReferences, 0.0000530 secs]2016-04-01T15:03:42.172-0700: 11025.637: [Preclean WeakReferences, 0.0006860 secs]2016-04-01T15:03:42.172-0700: 11025.638: [Preclean FinalReferences, 0.0005450 secs]2016-04-01T15:03:42.173-0700: 11025.639: [Preclean PhantomReferences, 0.0000230 secs]2016-04-01T15:03:42.197-0700: 11025.663: [CMS-concurrent-preclean: 0.025/0.026 secs] [Times: user=0.04 sys=0.01, real=0.03 secs]" + }, + { + "[10.749s][debug][gc,age ] GC(0) Desired survivor size 1572864 bytes, new threshold 15 (max threshold 15)\n" + }, + { + "[10.754s][trace][gc,age ] GC(0) - age 1: 2579584 bytes, 2579584 total" } }; } diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserTest.java index 4fbd777d..b7eee66b 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserTest.java @@ -11,8 +11,10 @@ import com.microsoft.gctoolkit.event.generational.ConcurrentSweep; import com.microsoft.gctoolkit.event.generational.FullGC; import com.microsoft.gctoolkit.event.generational.InitialMark; +import com.microsoft.gctoolkit.event.generational.PSYoungGen; import com.microsoft.gctoolkit.event.generational.ParNew; import com.microsoft.gctoolkit.event.jvm.JVMEvent; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.jvm.Diarizer; import com.microsoft.gctoolkit.parser.jvm.PreUnifiedDiarizer; import org.junit.jupiter.api.Assertions; diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParserFragmentTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParserFragmentTest.java index b63ec483..db0b162f 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParserFragmentTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParserFragmentTest.java @@ -2,8 +2,12 @@ // Licensed under the MIT License. package com.microsoft.gctoolkit.parser; +import com.microsoft.gctoolkit.event.CPUSummary; +import com.microsoft.gctoolkit.event.GCCause; +import com.microsoft.gctoolkit.event.MemoryPoolSummary; import com.microsoft.gctoolkit.event.g1gc.G1Young; import com.microsoft.gctoolkit.event.jvm.JVMEvent; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.jvm.Diarizer; import com.microsoft.gctoolkit.parser.diary.TestLogFile; import com.microsoft.gctoolkit.parser.jvm.UnifiedDiarizer; @@ -12,6 +16,7 @@ import java.io.IOException; import java.nio.file.Path; +import java.util.Iterator; import java.util.List; import static org.junit.jupiter.api.Assertions.fail; @@ -93,4 +98,88 @@ public void testNewDecoratorCombination() { fail(t); } } + + @Test + public void testSurvivorRecord() { + String[] lines = {"[0.016s][info][gc,heap] Heap region size: 1M", + "[0.018s][info][gc ] Using G1", + "[0.018s][info][gc,heap,coops] Heap address: 0x00000007fc000000, size: 64 MB, Compressed Oops mode: Zero based, Oop shift amount: 3\n" + + "[10.749s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)", + "[10.749s][info][gc,task ] GC(0) Using 8 workers of 8 for evacuation", + "[10.749s][debug][gc,age ] GC(0) Desired survivor size 1572864 bytes, new threshold 15 (max threshold 15)", + "[10.753s][trace][gc,age ] GC(0) Age table with threshold 15 (max threshold 15)", + "[10.754s][trace][gc,age ] GC(0) - age 1: 2579584 bytes, 2579584 total", + "[10.754s][info ][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Prepare TLABs: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Choose Collection Set: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Humongous Register: 0.0ms", + "[10.754s][info ][gc,phases ] GC(0) Evacuate Collection Set: 4.1ms", + "[10.754s][debug][gc,phases ] GC(0) Ext Root Scanning (ms): Min: 0.2, Avg: 0.9, Max: 1.7, Diff: 1.6, Sum: 7.3, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Claimed Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.8, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) AOT Root Scanning (ms): skipped", + "[10.754s][debug][gc,phases ] GC(0) Object Copy (ms): Min: 1.9, Avg: 2.8, Max: 3.5, Diff: 1.6, Sum: 22.7, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) Termination Attempts: Min: 1, Avg: 71.4, Max: 95, Diff: 94, Sum: 571, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1, Workers: 8", + "[10.754s][debug][gc,phases ] GC(0) GC Worker Total (ms): Min: 4.0, Avg: 4.1, Max: 4.1, Diff: 0.0, Sum: 32.5, Workers: 8", + "[10.754s][info ][gc,phases ] GC(0) Post Evacuate Collection Set: 0.3ms", + "[10.754s][debug][gc,phases ] GC(0) Code Roots Fixup: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Clear Card Table: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Reference Processing: 0.1ms", + "[10.754s][debug][gc,phases ] GC(0) Weak Processing: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Merge Per-Thread State: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Code Roots Purge: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Redirty Cards: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) DerivedPointerTable Update: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Free Collection Set: 0.1ms", + "[10.754s][debug][gc,phases ] GC(0) Humongous Reclaim: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Start New Collection Set: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Resize TLABs: 0.0ms", + "[10.754s][debug][gc,phases ] GC(0) Expand Heap After Collection: 0.0ms", + "[10.754s][info ][gc,phases ] GC(0) Other: 0.7ms", + "[10.754s][info ][gc,heap ] GC(0) Eden regions: 24->0(32)", + "[10.754s][info ][gc,heap ] GC(0) Survivor regions: 0->3(3)", + "[10.754s][info ][gc,heap ] GC(0) Old regions: 0->3", + "[10.754s][info ][gc,heap ] GC(0) Humongous regions: 0->0", + "[10.754s][info ][gc,metaspace ] GC(0) Metaspace: 15753K->15753K(1062912K)", + "[10.754s][info ][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 23M->5M(64M) 5.662ms", + "[10.754s][info ][gc,cpu ] GC(0) User=0.03s Sys=0.01s Real=0.00s" + }; + List jvmEvents = feedParser(lines); + + try { + Assertions.assertEquals(1, jvmEvents.size()); + Assertions.assertEquals(G1Young.class, jvmEvents.get(0).getClass()); + G1Young cycle = (G1Young) jvmEvents.get(0); + SurvivorRecord survivorRecord = cycle.getSurvivorRecord(); + Assertions.assertEquals(1572864, survivorRecord.getDesiredOccupancyAfterCollection()); + Assertions.assertEquals(15, survivorRecord.getMaxTenuringThreshold()); + Assertions.assertEquals(15, survivorRecord.getCalculatedTenuringThreshold()); + Assertions.assertEquals(2579584, survivorRecord.getBytesAtAge(1)); + Assertions.assertEquals(0.0, cycle.phaseDurationFor("Pre Evacuate Collection")); + Assertions.assertEquals(0.0041, cycle.phaseDurationFor("Evacuate Collection"), 0.0001); + Assertions.assertEquals(0.0003, cycle.phaseDurationFor("Post Evacuate Collection Set"), 0.00001); + Assertions.assertEquals(0.0007, cycle.phaseDurationFor("Other"), 0.00001); + Assertions.assertEquals(0.005662, cycle.getDuration(), 0.0000001); + Assertions.assertEquals(GCCause.G1_EVACUATION_PAUSE, cycle.getGCCause()); + MemoryPoolSummary memoryPoolSummary = cycle.getHeap(); + Assertions.assertEquals(23*1024, memoryPoolSummary.getOccupancyBeforeCollection()); + Assertions.assertEquals(5*1024, memoryPoolSummary.getOccupancyAfterCollection()); + Assertions.assertEquals(64*1024, memoryPoolSummary.getSizeAfterCollection()); + CPUSummary cpuSummary = cycle.getCpuSummary(); + Assertions.assertEquals(0.03, cpuSummary.getUser()); + Assertions.assertEquals(0.01, cpuSummary.getKernel()); + Assertions.assertEquals(0.00, cpuSummary.getWallClock()); + } catch(Throwable t) { + fail(t); + } + } } diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/UnifiedGenerationalEventsTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalEventsTest.java similarity index 75% rename from parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/UnifiedGenerationalEventsTest.java rename to parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalEventsTest.java index bb11bf06..9e4ff179 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/UnifiedGenerationalEventsTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalEventsTest.java @@ -1,6 +1,6 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. -package com.microsoft.gctoolkit.parser.patterns; +package com.microsoft.gctoolkit.parser; import com.microsoft.gctoolkit.event.MemoryPoolSummary; @@ -17,10 +17,8 @@ import com.microsoft.gctoolkit.event.generational.PSYoungGen; import com.microsoft.gctoolkit.event.generational.ParNew; import com.microsoft.gctoolkit.event.jvm.JVMEvent; +import com.microsoft.gctoolkit.event.jvm.SurvivorRecord; import com.microsoft.gctoolkit.jvm.Diarizer; -import com.microsoft.gctoolkit.parser.GCLogParser; -import com.microsoft.gctoolkit.parser.ParserTest; -import com.microsoft.gctoolkit.parser.UnifiedGenerationalParser; import com.microsoft.gctoolkit.parser.jvm.UnifiedDiarizer; import org.junit.jupiter.api.Test; @@ -332,15 +330,15 @@ public void testEnhancedMetaspaceRecord() { try { assertEquals(1, jvmEvents.size()); PSYoungGen collection = (PSYoungGen) jvmEvents.get(0); - assertEquals(53228,collection.getYoung().getOccupancyBeforeCollection()); - assertEquals(7148,collection.getYoung().getOccupancyAfterCollection()); - assertEquals(53248,collection.getYoung().getSizeAfterCollection()); - assertEquals(65568,collection.getTenured().getOccupancyBeforeCollection()); - assertEquals(111512,collection.getTenured().getOccupancyAfterCollection()); - assertEquals(121856,collection.getTenured().getSizeAfterCollection()); - assertEquals(116*1024,collection.getHeap().getOccupancyBeforeCollection()); - assertEquals(115*1024,collection.getHeap().getOccupancyAfterCollection()); - assertEquals(171*1024,collection.getHeap().getSizeAfterCollection()); + assertEquals(53228, collection.getYoung().getOccupancyBeforeCollection()); + assertEquals(7148, collection.getYoung().getOccupancyAfterCollection()); + assertEquals(53248, collection.getYoung().getSizeAfterCollection()); + assertEquals(65568, collection.getTenured().getOccupancyBeforeCollection()); + assertEquals(111512, collection.getTenured().getOccupancyAfterCollection()); + assertEquals(121856, collection.getTenured().getSizeAfterCollection()); + assertEquals(116 * 1024, collection.getHeap().getOccupancyBeforeCollection()); + assertEquals(115 * 1024, collection.getHeap().getOccupancyAfterCollection()); + assertEquals(171 * 1024, collection.getHeap().getSizeAfterCollection()); assertEquals(3646, collection.getPermOrMetaspace().getOccupancyBeforeCollection()); assertEquals(4864, collection.getPermOrMetaspace().getSizeBeforeCollection()); assertEquals(3646, collection.getPermOrMetaspace().getOccupancyAfterCollection()); @@ -358,4 +356,96 @@ public void testEnhancedMetaspaceRecord() { fail(cce.getMessage()); } } + + + @Test + public void parallelWithSurvivorRecordsTest() { + String[] lines = { + "[9.371s][info ][gc,start ] GC(18) Pause Young (Allocation Failure)", + "[9.371s][debug][gc,age ] GC(18) Desired survivor size 2097152 bytes, new threshold 1 (max threshold 15)", + "[9.371s][info ][gc,heap ] GC(18) PSYoungGen: 309244K(311296K)->454K(298496K) Eden: 308694K(308736K)->0K(297984K) From: 550K(2560K)->454K(512K)", + "[9.371s][info ][gc,heap ] GC(18) ParOldGen: 4018K(349696K)->4042K(349696K)", + "[9.371s][info ][gc,metaspace ] GC(18) Metaspace: 9573K(9856K)->9573K(9856K) NonClass: 8504K(8640K)->8504K(8640K) Class: 1069K(1216K)->1069K(1216K)", + "[9.371s][info ][gc ] GC(18) Pause Young (Allocation Failure) 305M->4M(633M) 0.242ms", + "[9.371s][info ][gc,cpu ] GC(18) User=0.01s Sys=0.00s Real=0.00s" + }; + + List jvmEvents = feedParser(lines); + assertEquals(1, jvmEvents.size()); + PSYoungGen collection = (PSYoungGen) jvmEvents.get(0); + assertEquals(9.371, collection.getDateTimeStamp().toSeconds()); + SurvivorRecord record = collection.getSurvivorRecord(); + assertNotNull(record); + assertEquals(15, record.getMaxTenuringThreshold()); + assertEquals(1, record.getCalculatedTenuringThreshold()); + assertEquals(2097152, record.getDesiredOccupancyAfterCollection()); + assertEquals(0, record.getBytesAtEachAge().length); + } + + @Test + public void serialWithSurvivorRecordsTest() { + + String[] lines = {"[8.726s][info ][gc,start ] GC(9) Pause Young (Allocation Failure)", + "[8.726s][debug][gc,age ] GC(9) Desired survivor size 8945664 bytes, new threshold 15 (max threshold 15)", + "[8.726s][trace][gc,age ] GC(9) Age table with threshold 15 (max threshold 15)", + "[8.726s][trace][gc,age ] GC(9) - age 1: 400368 bytes, 400368 total", + "[8.726s][trace][gc,age ] GC(9) - age 3: 304 bytes, 400672 total", + "[8.726s][trace][gc,age ] GC(9) - age 8: 32 bytes, 400704 total", + "[8.726s][trace][gc,age ] GC(9) - age 9: 554176 bytes, 954880 total", + "[8.726s][info ][gc,heap ] GC(9) DefNew: 140789K(157376K)->932K(157376K) Eden: 139857K(139904K)->0K(139904K) From: 932K(17472K)->932K(17472K)", + "[8.726s][info ][gc,heap ] GC(9) Tenured: 3357K(349568K)->3357K(349568K)", + "[8.726s][info ][gc,metaspace ] GC(9) Metaspace: 9628K(9856K)->9628K(9856K) NonClass: 8545K(8640K)->8545K(8640K) Class: 1082K(1216K)->1082K(1216K)", + "[8.727s][info ][gc ] GC(9) Pause Young (Allocation Failure) 140M->4M(495M) 0.445ms", + "[8.727s][info ][gc,cpu ] GC(9) User=0.00s Sys=0.00s Real=0.00s" + }; + + List jvmEvents = feedParser(lines); + assertEquals(1, jvmEvents.size()); + DefNew collection = (DefNew) jvmEvents.get(0); + assertEquals(8.726, collection.getDateTimeStamp().toSeconds()); + SurvivorRecord record = collection.getSurvivorRecord(); + assertNotNull(record); + assertEquals(15, record.getMaxTenuringThreshold()); + assertEquals(15, record.getCalculatedTenuringThreshold()); + assertEquals(8945664, record.getDesiredOccupancyAfterCollection()); + assertEquals(16, record.getBytesAtEachAge().length); + int[] bytesAtAge = {0, 400368, 0, 304, 0, 0, 0, 0, 32, 554176, 0, 0, 0, 0, 0, 0}; + for (int i = 1; i < bytesAtAge.length; i++) { + assertEquals(bytesAtAge[i], record.getBytesAtAge(i)); + } + assertThrows(IndexOutOfBoundsException.class, () -> record.getBytesAtAge(16)); + } + + @Test + public void cmsWithSurvivorRecordsTest() { + + String[] lines = {"[11.633s][info ][gc,start ] GC(12) Pause Young (Allocation Failure)", + "[11.633s][info ][gc,task ] GC(12) Using 9 workers of 9 for evacuation", + "[11.634s][debug][gc,age ] GC(12) Desired survivor size 8945664 bytes, new threshold 6 (max threshold 6)", + "[11.634s][trace][gc,age ] GC(12) Age table with threshold 6 (max threshold 6)", + "[11.634s][trace][gc,age ] GC(12) - age 1: 400208 bytes, 400208 total", + "[11.634s][trace][gc,age ] GC(12) - age 6: 304 bytes, 400512 total", + "[11.634s][info ][gc,heap ] GC(12) ParNew: 140026K->398K(157376K)", + "[11.634s][info ][gc,heap ] GC(12) CMS: 3662K->3662K(349568K)", + "[11.634s][info ][gc,metaspace ] GC(12) Metaspace: 15714K(16256K)->15714K(16256K) NonClass: 14027K(14336K)->14027K(14336K) Class: 1686K(1920K)->1686K(1920K)", + "[11.634s][info ][gc ] GC(12) Pause Young (Allocation Failure) 140M->3M(495M) 0.430ms", + "[11.634s][info ][gc,cpu ] GC(12) User=0.00s Sys=0.00s Real=0.00s", + }; + List jvmEvents = feedParser(lines); + assertEquals(1, jvmEvents.size()); + ParNew collection = (ParNew) jvmEvents.get(0); + + assertEquals(11.633, collection.getDateTimeStamp().toSeconds()); + SurvivorRecord record = collection.getSurvivorRecord(); + assertNotNull(record); + assertEquals(6, record.getMaxTenuringThreshold()); + assertEquals(6, record.getCalculatedTenuringThreshold()); + assertEquals(8945664, record.getDesiredOccupancyAfterCollection()); + assertEquals(7, record.getBytesAtEachAge().length); + int[] bytesAtAge = {0, 400208, 0, 0, 0, 0, 304}; + for (int i = 1; i < bytesAtAge.length; i++) { + assertEquals(bytesAtAge[i], record.getBytesAtAge(i)); + } + assertThrows(IndexOutOfBoundsException.class, () -> record.getBytesAtAge(7)); + } } diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/unittests/UnifiedGenerationalParserTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/unittests/UnifiedGenerationalParserTest.java index cf5f7b1a..ac81d721 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/unittests/UnifiedGenerationalParserTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/unittests/UnifiedGenerationalParserTest.java @@ -82,15 +82,17 @@ public void testSerialLogs() { } private static final String[] serial = { - "factorization-serialgc-tip.log" + "factorization-serialgc-tip.log", + "factorization-serialgc-jdk21.log" }; private static final int[] serialNumberOfDifferentCollectors = { - 2, + 2, 2 }; private static final int[][] serialCounts = { // 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17 - { 0, 13, 0, 0, 0, 0, 0, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0}, + { 0, 13, 0, 0, 0, 0, 0, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0}, // 17 + { 0, 812, 0, 0, 0, 0, 0, 0, 0, 0, 24, 0, 0, 0, 0, 0, 0, 0}, // 835 }; }