Skip to content

Commit f754b3b

Browse files
kcpeppekariannaDavid Grieve
authored
424 (#432)
* bug: intermediate commit to allow work on another bug * bug: add more robust handling of IllegalArgumentException in GCToolKit::analyize * tidy: remove debug to stdout to logging framework * refactor: Ensure DateTimeStamp cannot be malformed and it behaves if the timestamp is missing * refactor: update pom for new GC log test data bundle * tidy: address comments from PR * Update parser/src/main/java/com/microsoft/gctoolkit/parser/GCLogParser.java * feature: first push to combine CMS parser with GenerationalHeapParser * depreciate: depreciated the CMS preunified event source * refactor: get all tests to pass * refactor: continue to get tests to pass * refactor: continue to get tests to pass * refactor: collapse CMS phases parser into generational parser * refactor: GenerationalHeapParser was duplicating CMF failures under certain conditions * refactor: ensure GC log is closed when discovering the format * refactor: add test for reported bug * refactor: add ability to parse very simple logs preunified logs * refactor: remove no longer needed print statement * refactor: tidy from review * refactor: support date stamps only for preunified logs * refactor: bump version of gctoolkit testdata to support new tests * refactor: small code cleanups * Update parser/src/main/java/com/microsoft/gctoolkit/parser/AbstractLogTrace.java Co-authored-by: Martijn Verburg <[email protected]> * tidy: cleanup from review and added more tests * refactor: adjust unified generational GC log parser to produce SystemGC events * refactor: update source data to include new serial GC log file * refactor: prep for merge with upstream/main * refactor: add survivor record to the G1Young events * refactor: adding in tenuring record * refactor: update testdata version # * refactor: add in tests for Survivor records found in GCEvent * refactor: update test data * fix highly unlikely AIOBE * do not range check age arg in SurvivorRecord --------- Co-authored-by: Martijn Verburg <[email protected]> Co-authored-by: David Grieve <[email protected]>
1 parent caf5101 commit f754b3b

File tree

14 files changed

+321
-43
lines changed

14 files changed

+321
-43
lines changed

api/src/main/java/com/microsoft/gctoolkit/event/g1gc/G1Young.java

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
import com.microsoft.gctoolkit.event.GarbageCollectionTypes;
77
import com.microsoft.gctoolkit.event.StatisticalSummary;
88
import com.microsoft.gctoolkit.event.UnifiedStatisticalSummary;
9+
import com.microsoft.gctoolkit.event.jvm.SurvivorRecord;
910
import com.microsoft.gctoolkit.time.DateTimeStamp;
1011

1112
import java.util.Iterator;
@@ -36,6 +37,7 @@ public class G1Young extends G1RealPause {
3637
private StatisticalSummary workerTotal;
3738
private StatisticalSummary processedBuffersSummary;
3839
private boolean toSpaceExhausted = false;
40+
private SurvivorRecord survivorRecord;
3941

4042
private final Map<String, StatisticalSummary> parallelPhaseSummaries = new ConcurrentHashMap<>();
4143
private final Map<String, Double> phaseDurations = new ConcurrentHashMap<>();
@@ -196,6 +198,14 @@ public void addWorkerActivity(String group, StatisticalSummary statisticalSummar
196198
workerTotal = statisticalSummary;
197199
}
198200

201+
public void add(SurvivorRecord record) {
202+
this.survivorRecord = record;
203+
}
204+
205+
public SurvivorRecord getSurvivorRecord() {
206+
return survivorRecord;
207+
}
208+
199209
public StatisticalSummary getWorkerOther() {
200210
return this.workerOther;
201211
}

api/src/main/java/com/microsoft/gctoolkit/event/generational/GenerationalGCPauseEvent.java

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
import com.microsoft.gctoolkit.event.GarbageCollectionTypes;
88
import com.microsoft.gctoolkit.event.MemoryPoolSummary;
99
import com.microsoft.gctoolkit.event.ReferenceGCSummary;
10+
import com.microsoft.gctoolkit.event.jvm.SurvivorRecord;
1011
import com.microsoft.gctoolkit.time.DateTimeStamp;
1112

1213
public abstract class GenerationalGCPauseEvent extends GenerationalGCEvent {
@@ -23,6 +24,7 @@ public abstract class GenerationalGCPauseEvent extends GenerationalGCEvent {
2324
private double stringTableProcessingTime;
2425
private double symbolAndStringTableProcessingTime;
2526
private BinaryTreeDictionary binaryTreeDictionary;
27+
private SurvivorRecord survivorRecord;
2628

2729
private CPUSummary cpuSummary;
2830

@@ -114,6 +116,14 @@ public void addClassUnloadingAndStringTableProcessingDurations(double classUnloa
114116
this.symbolAndStringTableProcessingTime = symbolAndStringTable;
115117
}
116118

119+
public void add(SurvivorRecord record) {
120+
this.survivorRecord = record;
121+
}
122+
123+
public SurvivorRecord getSurvivorRecord() {
124+
return survivorRecord;
125+
}
126+
117127
public double getClassUnloadingProcessingTime() {
118128
return this.classUnloadingProcessingTime;
119129
}

api/src/main/java/com/microsoft/gctoolkit/event/jvm/SurvivorRecord.java

Lines changed: 11 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -16,8 +16,8 @@ public class SurvivorRecord extends JVMEvent {
1616
private int maxTenuringThreshold;
1717

1818
// JDK bug, we have now seen a max tenuring threshold of 32, even 64
19-
// Fold anything older than 15 back into the 15th slot
20-
private ArrayList<Long> bytesAtAge = null;
19+
// Fold anything older than maxTenuringThreshold back into the maxTenuringThreshold slot
20+
private long[] bytesAtAge;
2121

2222
public SurvivorRecord(DateTimeStamp timeStamp, long desiredOccupancy, int calculatedTenuringThreshold, int maxTenuringThreshold) {
2323
super(timeStamp, 0.0d);
@@ -56,31 +56,30 @@ public int getMaxTenuringThreshold() {
5656

5757
public long getBytesAtAge(int age) {
5858
if (this.bytesAtAge == null) return 0L;
59-
return this.bytesAtAge.get(age);
59+
return this.bytesAtAge[age];
6060
}
6161

6262
/*
6363
* There is a bug in the JVM that allows tenuring threshold to appear to be greater than 15.
64-
* Fold anything greater than 15 into 15.
65-
*
64+
* Fold anything greater than maxTenuringThreshold into maxTenuringThreshold.
6665
*/
6766
public void add(int age, long bytes) {
6867

6968
if (bytesAtAge == null) {
70-
bytesAtAge = new ArrayList<>();
71-
bytesAtAge.add(0L); //throw away the first slow.
69+
bytesAtAge = new long[maxTenuringThreshold+1];
70+
bytesAtAge[0] = 0L; //throw away the first slot.
7271
}
7372

7473
if (age <= maxTenuringThreshold) {
75-
bytesAtAge.add(bytes);
74+
bytesAtAge[age] = bytes;
7675
} else {
77-
bytesAtAge.set(maxTenuringThreshold, bytesAtAge.get(maxTenuringThreshold) + bytes);
76+
bytesAtAge[maxTenuringThreshold] += bytes;
7877
}
7978
}
8079

81-
public Long[] getBytesAtEachAge() {
80+
public long[] getBytesAtEachAge() {
8281
if (bytesAtAge == null)
83-
return new Long[0];
84-
return bytesAtAge.toArray(new Long[0]);
82+
return new long[0];
83+
return bytesAtAge;
8584
}
8685
}

gclogs/pom.xml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,7 @@
1717
<packaging>pom</packaging>
1818

1919
<properties>
20-
<gctoolkit-testdata-version>1.0.10</gctoolkit-testdata-version>
20+
<gctoolkit-testdata-version>1.0.12</gctoolkit-testdata-version>
2121
</properties>
2222

2323
<build>

parser/src/main/java/com/microsoft/gctoolkit/parser/ForwardReference.java

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44

55
import com.microsoft.gctoolkit.event.CPUSummary;
66
import com.microsoft.gctoolkit.event.GCCause;
7+
import com.microsoft.gctoolkit.event.jvm.SurvivorRecord;
78
import com.microsoft.gctoolkit.parser.jvm.Decorators;
89
import com.microsoft.gctoolkit.time.DateTimeStamp;
910

@@ -15,6 +16,7 @@ public class ForwardReference {
1516
private double duration = -1.0d;
1617
private GCCause gcCause = GCCause.UNKNOWN_GCCAUSE;
1718
private CPUSummary cpuSummary = null;
19+
SurvivorRecord survivorRecord = null;
1820

1921
ForwardReference(Decorators decorators, int id) {
2022
this.gcID = id;
@@ -69,4 +71,17 @@ Decorators getDecorators() {
6971
return decorators;
7072
}
7173

74+
public void survivorRecord(SurvivorRecord survivorRecord) {
75+
this.survivorRecord = survivorRecord;
76+
}
77+
78+
public void addAgeBreakout(int age, long volume) {
79+
if (this.survivorRecord == null)
80+
return;
81+
this.survivorRecord.add(age, volume);
82+
}
83+
84+
public SurvivorRecord getSurvivorRecord() {
85+
return this.survivorRecord;
86+
}
7287
}

parser/src/main/java/com/microsoft/gctoolkit/parser/G1GCForwardReference.java

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -782,6 +782,8 @@ private G1Young buildYoung(G1Young collection) {
782782
if (toSpaceExhausted) collection.toSpaceExhausted();
783783
if (hasReferenceGCSummary())
784784
collection.add(generateReferenceGCSummary());
785+
if (survivorRecord != null)
786+
collection.add(survivorRecord);
785787
collection.addCPUSummary(getCPUSummary());
786788
return collection;
787789
}

parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParser.java

Lines changed: 24 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
import com.microsoft.gctoolkit.event.g1gc.G1GCPauseEvent;
1616
import com.microsoft.gctoolkit.event.jvm.JVMEvent;
1717
import com.microsoft.gctoolkit.event.jvm.JVMTermination;
18+
import com.microsoft.gctoolkit.event.jvm.SurvivorRecord;
1819
import com.microsoft.gctoolkit.jvm.Diary;
1920
import com.microsoft.gctoolkit.message.ChannelName;
2021
import com.microsoft.gctoolkit.message.JVMEventChannel;
@@ -47,7 +48,7 @@
4748
* - pause time if it is reported or can be calculated
4849
* todo: me
4950
*/
50-
public class UnifiedG1GCParser extends UnifiedGCLogParser implements UnifiedG1GCPatterns {
51+
public class UnifiedG1GCParser extends UnifiedGCLogParser implements UnifiedG1GCPatterns, TenuredPatterns {
5152

5253
private static final Logger LOGGER = Logger.getLogger(UnifiedG1GCParser.class.getName());
5354

@@ -154,6 +155,8 @@ public class UnifiedG1GCParser extends UnifiedGCLogParser implements UnifiedG1GC
154155
parseRules.put(REBUILD_FREELIST, this::noop);
155156
parseRules.put(NEW_CSET, this::noop);
156157
parseRules.put(RESIZE_TLAB, this::noop);
158+
parseRules.put(TENURING_SUMMARY, this::tenuringSummary);
159+
parseRules.put(TENURING_AGE_BREAKDOWN, this::tenuringAgeBreakout);
157160
}
158161

159162
public UnifiedG1GCParser() {
@@ -688,6 +691,25 @@ private void fullStringSymbolTable(GCLogTrace trace, String line) {
688691
// forwardReference.scrubStringSymbolTableDuration(trace.getMillisecondDurationInSeconds());
689692
}
690693

694+
/**
695+
* Capture logged tenuring summary data
696+
* @param trace
697+
* @param line
698+
*/
699+
private void tenuringSummary(GCLogTrace trace, String line) {
700+
forwardReference.survivorRecord(new SurvivorRecord(getClock(), trace.getLongGroup(1), trace.getIntegerGroup(2), trace.getIntegerGroup(3)));
701+
}
702+
703+
/**
704+
* Capture logged age table data
705+
* @param trace
706+
* @param line
707+
*/
708+
private void tenuringAgeBreakout(GCLogTrace trace, String line) {
709+
notYetImplemented(trace,line);
710+
forwardReference.addAgeBreakout(trace.getIntegerGroup(1), trace.getLongGroup(2));
711+
}
712+
691713
/**
692714
* records a concurrent phase of a concurrent cycle. After the event has been recorded, all other events
693715
* that occurred during the concurrent event will be recorded.
@@ -742,8 +764,6 @@ private void jvmExit(GCLogTrace trace, String s) {
742764
}
743765

744766
private boolean ignoreFrequentlySeenButUnwantedLines(String line) {
745-
if (line.contains("Desired survivor size")) return true;
746-
if (line.contains("Age table with threshold")) return true;
747767
if (line.contains("safepoint")) return true;
748768
if (line.contains(") Skipped phase ")) return true;
749769
if (line.contains(" Total Min: ")) return true;
@@ -754,7 +774,7 @@ private boolean ignoreFrequentlySeenButUnwantedLines(String line) {
754774
if (line.contains(" StringTable Weak Min:")) return true;
755775
if (line.contains(" ResolvedMethodTable Weak Min:")) return true;
756776
if (line.contains(" JNI Weak Min:")) return true;
757-
return line.contains(" - age ");
777+
return false;
758778
}
759779

760780
/**

parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedGenerationalParser.java

Lines changed: 29 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
import com.microsoft.gctoolkit.event.generational.SystemGC;
2626
import com.microsoft.gctoolkit.event.generational.YoungGC;
2727
import com.microsoft.gctoolkit.event.jvm.JVMTermination;
28+
import com.microsoft.gctoolkit.event.jvm.SurvivorRecord;
2829
import com.microsoft.gctoolkit.jvm.Diary;
2930
import com.microsoft.gctoolkit.message.ChannelName;
3031
import com.microsoft.gctoolkit.message.JVMEventChannel;
@@ -63,7 +64,7 @@
6364
* - from, to, configured
6465
* - pause time if it is reported or can be calculated
6566
*/
66-
public class UnifiedGenerationalParser extends UnifiedGCLogParser implements UnifiedGenerationalPatterns {
67+
public class UnifiedGenerationalParser extends UnifiedGCLogParser implements UnifiedGenerationalPatterns, TenuredPatterns {
6768

6869
private static final Logger LOGGER = Logger.getLogger(UnifiedGenerationalParser.class.getName());
6970

@@ -100,6 +101,8 @@ public class UnifiedGenerationalParser extends UnifiedGCLogParser implements Uni
100101
parseRules.put(JVM_EXIT, this::jvmExit);
101102
parseRules.put(END_OF_FILE, this::jvmExit);
102103
parseRules.put(METASPACE_DETAILED, this::metaSpaceDetails);
104+
parseRules.put(TENURING_SUMMARY, this::tenuringSummary);
105+
parseRules.put(TENURING_AGE_BREAKDOWN, this::tenuringAgeBreakout);
103106

104107
}
105108

@@ -229,6 +232,26 @@ private void youngDetails(GCLogTrace trace, String line) {
229232
pauseEvent.setHeap(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(2));
230233
}
231234

235+
/**
236+
* Capture logged tenuring summary data
237+
* @param trace
238+
* @param line
239+
*/
240+
private void tenuringSummary(GCLogTrace trace, String line) {
241+
if ( pauseEvent != null)
242+
pauseEvent.survivorRecord(new SurvivorRecord(getClock(), trace.getLongGroup(1), trace.getIntegerGroup(2), trace.getIntegerGroup(3)));
243+
}
244+
245+
/**
246+
* Capture logged age table data
247+
* @param trace
248+
* @param line
249+
*/
250+
private void tenuringAgeBreakout(GCLogTrace trace, String line) {
251+
if (pauseEvent != null)
252+
pauseEvent.addAgeBreakout(trace.getIntegerGroup(1), trace.getLongGroup(2));
253+
}
254+
232255
/**
233256
* If the concurrentCyclePauseEvent has not been recorded, something has gone wrong and it's likely
234257
* that it doesn't have a consistent state. The default action is to lose it.
@@ -449,13 +472,14 @@ private GenerationalGCPauseEvent buildYoungEvent(GenerationalForwardReference fo
449472
youngCollection = new PSYoungGen(forwardReference.getStartTime(), forwardReference.getGCCause(), forwardReference.getDuration());
450473
break;
451474
default:
452-
LOGGER.warning(forwardReference.getGarbageCollectionType() + " not recognized");
475+
throw new IllegalStateException(forwardReference.getGarbageCollectionType() + " not recognized");
453476
}
454477

455478
fillOutMemoryPoolData(youngCollection, forwardReference);
456479
fillOutMetaspaceData(youngCollection, forwardReference);
457480
youngCollection.add(forwardReference.getCPUSummary());
458-
// add in reference processing
481+
youngCollection.add(forwardReference.getSurvivorRecord());
482+
// todo: add in reference processing
459483
return youngCollection;
460484
}
461485

@@ -519,7 +543,7 @@ private GenerationalGCPauseEvent buildPauseEvent(GenerationalForwardReference fo
519543
return buildInitialMark(forwardReference);
520544
case Remark:
521545
return buildRemark(forwardReference);
522-
case PSFull: //todo:
546+
case PSFull:
523547
case FullGC:
524548
case Full:
525549
return buildFullGC(forwardReference);
@@ -565,8 +589,7 @@ private boolean ignoreFrequentlySeenButUnwantedLines(String line) {
565589
if (line.contains("exit"))
566590
if (line.contains("used")) return true;
567591
if (line.contains("workers")) return true;
568-
if (line.contains("Heap address")) return true;
569-
return line.contains("Desired") || line.contains("Age table") || line.contains("- age ");
592+
return line.contains("Heap address");
570593
}
571594

572595
@Override

parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCUnifiedParserRulesTest.java

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@
1212
import static com.microsoft.gctoolkit.parser.CommonTestHelper.captureTest;
1313
import static org.junit.jupiter.api.Assertions.*;
1414

15-
public class G1GCUnifiedParserRulesTest implements UnifiedG1GCPatterns {
15+
public class G1GCUnifiedParserRulesTest implements UnifiedG1GCPatterns, TenuredPatterns {
1616

1717
/**
1818
* The rules are;
@@ -152,7 +152,9 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
152152
WEAK_PROCESSING,
153153
CLEANUP__FINALIZE_CONC_MARK,
154154
CONCURRENT_UNDO_CYCLE_START,
155-
CONCURRENT_UNDO_CYCLE_END // 70
155+
CONCURRENT_UNDO_CYCLE_END , // 70
156+
TENURING_SUMMARY,
157+
TENURING_AGE_BREAKDOWN
156158
};
157159

158160
/*
@@ -447,6 +449,12 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
447449
},
448450
{ // 70
449451
"[155.836s][info ][gc ] GC(2457) Concurrent Undo Cycle 49.351ms",
452+
},
453+
{ // 71
454+
"[10.749s][debug][gc,age ] GC(0) Desired survivor size 1572864 bytes, new threshold 15 (max threshold 15)\n"
455+
},
456+
{ // 72
457+
"[10.754s][trace][gc,age ] GC(0) - age 1: 2579584 bytes, 2579584 total"
450458
}
451459

452460
// Remaining lines which may not need to be parsed...

parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserRulesTest.java

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@
99
import static com.microsoft.gctoolkit.parser.CommonTestHelper.captureTest;
1010
import static org.junit.jupiter.api.Assertions.*;
1111

12-
public class GenerationalHeapParserRulesTest implements SimplePatterns, SerialPatterns, ParallelPatterns, CMSPatterns, ICMSPatterns {
12+
public class GenerationalHeapParserRulesTest implements SimplePatterns, SerialPatterns, ParallelPatterns, CMSPatterns, ICMSPatterns, TenuredPatterns {
1313

1414
private static final Logger LOGGER = Logger.getLogger(GenerationalHeapParserRulesTest.class.getName());
1515

@@ -250,7 +250,9 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
250250
// CMF_LARGE_BLOCK,
251251
// //this rule must be evaluated before CONCURRENT_PHASE_END_BLOCK
252252
// ABORT_PRECLEAN_DUE_TO_TIME_CLAUSE,
253-
PRECLEAN_REFERENCE
253+
PRECLEAN_REFERENCE,
254+
TENURING_SUMMARY,
255+
TENURING_AGE_BREAKDOWN
254256
};
255257

256258
private String[][] lines = {
@@ -591,6 +593,12 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
591593
// },
592594
{
593595
"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]"
596+
},
597+
{
598+
"[10.749s][debug][gc,age ] GC(0) Desired survivor size 1572864 bytes, new threshold 15 (max threshold 15)\n"
599+
},
600+
{
601+
"[10.754s][trace][gc,age ] GC(0) - age 1: 2579584 bytes, 2579584 total"
594602
}
595603
};
596604
}

0 commit comments

Comments
 (0)