Skip to content

Commit 145f1a1

Browse files
jlittle-ptcjlittle-ptc
authored
#433 - Fixes and tests for Pre-Unified G1GC and Parallel (#438)
* #433 - Adjust offsets to match G1GC Young event examples. * Fix offset issue in GenerationalHeapParser with psYoungNoDetails * Update incorrect offsets in GenerationalHeapParser and PreUnifiedG1GCParser and add test cases to expose issues in future. * Fixed an additional offset issue and added some validation tests that helped expose it. * Fixed an additional offset issue and added some validation tests that helped expose it. * Adding additional utility functions to ParserTest and test cases for event sequences in Pre-unified G1 logs. * Additional event format test cases for GenerationalParser * Fix FullGC in GenerationalHeapParser and add validating case
1 parent 13a5e62 commit 145f1a1

File tree

6 files changed

+674
-12
lines changed

6 files changed

+674
-12
lines changed

‎parser/src/main/java/com/microsoft/gctoolkit/parser/GenerationalHeapParser.java

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1583,6 +1583,8 @@ public void psYoungGen(GCLogTrace trace, String line) {
15831583
publish(collection);
15841584
}
15851585

1586+
// #433 - Offset for this call needed to be incremented by 3 to 7 (previously 4)
1587+
//23.331: [Full GC (Metadata GC Threshold) 17386K->16928K(415232K), 0.0498462 secs]
15861588
public void psFull(GCLogTrace trace, String line) {
15871589
FullGC collection;
15881590
GCCause cause = trace.gcCause();
@@ -1591,24 +1593,25 @@ public void psFull(GCLogTrace trace, String line) {
15911593
} else {
15921594
collection = new FullGC(trace.getDateTimeStamp(), cause, trace.getDuration());
15931595
}
1594-
collection.add(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(4));
1596+
collection.add(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(7));
15951597
publish(collection);
15961598
}
15971599

1600+
// #433 - Offset for this call needed to be incremented by 3 to 7. (previously 4)
1601+
//13.563: [GC (Allocation Failure) 886080K->31608K(1986432K), 0.0392109 secs]
15981602
public void psYoungNoDetails(GCLogTrace trace, String line) {
15991603
GCCause cause = trace.gcCause();
16001604
if (GCCause.JAVA_LANG_SYSTEM == cause) { // bug in 1.8.0_121 makes Full System.gc() look like a young collection
16011605
SystemGC collection = new SystemGC(trace.getDateTimeStamp(), GCCause.JAVA_LANG_SYSTEM, trace.getDuration());
1602-
collection.add(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(4));
1606+
collection.add(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(7));
16031607
publish(collection);
16041608
} else {
16051609
PSYoungGen collection = new PSYoungGen(trace.getDateTimeStamp(), cause, trace.getDuration());
1606-
collection.add(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(4));
1610+
collection.add(trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(7));
16071611
publish(collection);
16081612
}
16091613
}
16101614

1611-
//
16121615
public void psYoungGenReferenceProcessingSplit(GCLogTrace trace, String line) {
16131616
scavengeTimeStamp = getClock();
16141617
gcCauseForwardReference = trace.gcCause();

‎parser/src/main/java/com/microsoft/gctoolkit/parser/PreUnifiedG1GCParser.java

Lines changed: 14 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -366,13 +366,16 @@ private void ignore(GCLogTrace trace, String line) {
366366
//2014-02-22T10:49:26.508-0100: 7.498: [GC pause (G1 Evacuation Pause) (mixed), 0.0026410 secs]
367367
//26.893: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.1709670 secs]
368368
//115.421: [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0476190 secs]
369+
//2025-03-23T03:57:20.841+0000: 661.878: [GC pause (System.gc()) (young) (initial-mark), 0.0502295 secs]
369370
private void processYoungGenCollection(GCLogTrace trace, String line) {
370371
boolean initialMark = trace.contains(8, "initial-mark");
371372
boolean tospaceExhausted = trace.contains(trace.groupCount() - 2, "to-space");
372373

373374
if (trace.contains(7, "young")) {
374375
if (initialMark)
375-
forwardReference = new G1YoungInitialMark(trace.getDateTimeStamp(), trace.gcCause(3, 0), trace.getDoubleGroup(trace.groupCount()));
376+
// jlittle-ptc: Cause was misaligned, originally pointed to group 3, but seems to be consistently in group 6.
377+
// which is default for trace.gcCause(), and would match with other off-by-3 issues I've found.
378+
forwardReference = new G1YoungInitialMark(trace.getDateTimeStamp(), trace.gcCause(), trace.getDoubleGroup(trace.groupCount()));
376379
else
377380
forwardReference = new G1Young(trace.getDateTimeStamp(), trace.gcCause(), trace.getDoubleGroup(trace.groupCount()));
378381
if (tospaceExhausted)
@@ -389,19 +392,25 @@ private void processYoungGenCollection(GCLogTrace trace, String line) {
389392
//5.478: [GC pause (young) 8878K->5601K(13M), 0.0027650 secs]
390393
//1566.108: [GC pause (mixed) 7521K->5701K(13M), 0.0030090 secs]
391394
//549.243: [GC pause (young) (initial-mark) 9521K->7824K(13M), 0.0021590 secs]
395+
//0.867: [GC pause (G1 Evacuation Pause) (young) 52816K->9563K(1024M), 0.0225122 secs]
396+
//1834339.155: [GC pause (G1 Evacuation Pause) (mixed) 309M->141M(1111M), 0.0188779 secs]
392397
private void processYoung(GCLogTrace trace, String line) {
393-
MemoryPoolSummary summary = trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(9);
394-
if ("young".equals(trace.getGroup(4))) {
398+
// #433 - All offsets in method incremented by 3 as they weren't matching the correct groups.
399+
MemoryPoolSummary summary = trace.getOccupancyBeforeAfterWithMemoryPoolSizeSummary(12);
400+
if ("young".equals(trace.getGroup(7))) {
395401
G1Young collection = null;
396-
if (trace.getGroup(6) == null)
402+
if (trace.getGroup(9) == null)
397403
collection = new G1Young(getClock(), trace.gcCause(), trace.getPauseTime());
398404
else {
405+
// Sample lines not currently parsed:
406+
//1.488: [GC pause (Metadata GC Threshold) (young) (initial-mark) 31558K->14662K(1024M), 0.0073758 secs]
407+
//2439412.011: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 616M->187M(1131M), 0.0484678 secs]
399408
trace.notYetImplemented();
400409
return;
401410
}
402411
collection.addMemorySummary(summary);
403412
publish(collection);
404-
} else if ("mixed".equals(trace.getGroup(4))) {
413+
} else if ("mixed".equals(trace.getGroup(7))) {
405414
G1Young collection = new G1Mixed(getClock(), trace.gcCause(), trace.getPauseTime());
406415
collection.addMemorySummary(summary);
407416
publish(collection);

‎parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCParserRulesTest.java

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -89,7 +89,8 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
8989
CONCURRENT_START_V3,
9090
CONCURRENT_START_V4,
9191
CONCURRENT_START_V5, // 40
92-
G1_CONCURRENT_ABORT
92+
G1_CONCURRENT_ABORT,
93+
YOUNG
9394
};
9495

9596
private String[][] lines = {
@@ -239,6 +240,12 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
239240
},
240241
{ // 41
241242
"27105.565: [GC concurrent-mark-abort]"
243+
},
244+
{ // 42
245+
"5.478: [GC pause (young) 8878K->5601K(13M), 0.0027650 secs]",
246+
"549.243: [GC pause (young) (initial-mark) 9521K->7824K(13M), 0.0021590 secs]",
247+
"1566.108: [GC pause (mixed) 7521K->5701K(13M), 0.0030090 secs]",
248+
"0.867: [GC pause (G1 Evacuation Pause) (young) 52816K->9563K(1024M), 0.0225122 secs]"
242249
}
243250
};
244251
}

‎parser/src/test/java/com/microsoft/gctoolkit/parser/GenerationalHeapParserTest.java

Lines changed: 196 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
// Licensed under the MIT License.
33
package com.microsoft.gctoolkit.parser;
44

5+
import com.microsoft.gctoolkit.event.GCCause;
56
import com.microsoft.gctoolkit.event.generational.AbortablePreClean;
67
import com.microsoft.gctoolkit.event.generational.CMSRemark;
78
import com.microsoft.gctoolkit.event.generational.ConcurrentMark;
@@ -11,12 +12,17 @@
1112
import com.microsoft.gctoolkit.event.generational.ConcurrentSweep;
1213
import com.microsoft.gctoolkit.event.generational.FullGC;
1314
import com.microsoft.gctoolkit.event.generational.InitialMark;
15+
import com.microsoft.gctoolkit.event.generational.PSFullGC;
1416
import com.microsoft.gctoolkit.event.generational.PSYoungGen;
1517
import com.microsoft.gctoolkit.event.generational.ParNew;
18+
import com.microsoft.gctoolkit.event.generational.SystemGC;
19+
import com.microsoft.gctoolkit.event.generational.YoungGC;
1620
import com.microsoft.gctoolkit.event.jvm.JVMEvent;
1721
import com.microsoft.gctoolkit.event.jvm.SurvivorRecord;
1822
import com.microsoft.gctoolkit.jvm.Diarizer;
1923
import com.microsoft.gctoolkit.parser.jvm.PreUnifiedDiarizer;
24+
import com.microsoft.gctoolkit.time.DateTimeStamp;
25+
2026
import org.junit.jupiter.api.Assertions;
2127
import org.junit.jupiter.api.Test;
2228

@@ -213,7 +219,196 @@ public void parallelYoungGenTest() {
213219
assertEquals(7, jvmEvents.size());
214220
assertEquals(103.387, getParser().diary.getTimeOfFirstEvent().toSeconds());
215221
}
216-
222+
223+
@Test
224+
// jlittle-ptc: Added to validate changes in https://github.com/microsoft/gctoolkit/issues/433
225+
// Fails without changes, passes with changes.
226+
public void psYoungNoDetailsTest() {
227+
String[] lines = {
228+
"13.563: [GC (Allocation Failure) 886080K->31608K(1986432K), 0.0392109 secs]",
229+
};
230+
231+
List<JVMEvent> jvmEvents = feedParser(lines);
232+
assertEquals(1, jvmEvents.size());
233+
234+
assertTrue(jvmEvents.get(0) instanceof PSYoungGen);
235+
236+
PSYoungGen evt = (PSYoungGen) jvmEvents.get(0);
237+
assertMemoryPoolValues(evt.getHeap(), 886080, 1986432, 31608, 1986432);
238+
}
239+
240+
@Test
241+
void testGenerationalNoDetailsLines() {
242+
String[] lines = {
243+
// 0 - Normal GC
244+
"75.240: [GC 525312K->16552K(2013696K), 0.1105640 secs]",
245+
246+
// 1 - Full GC
247+
"8357.379: [Full GC 1379524K->1236761K(2787392K), 43.3665438 secs]",
248+
249+
// 2 - InitialMark
250+
"25293.283: [GC 2548071K(3028408K), 0.0743383 secs]"
251+
};
252+
253+
int expectedEventCount = 3;
254+
255+
List<JVMEvent> jvmEvents = feedParser(lines);
256+
assertEquals(jvmEvents.size(), expectedEventCount);
257+
258+
// 0 - YoungGC
259+
assertTrue(jvmEvents.get(0) instanceof YoungGC);
260+
YoungGC evt0 = ((YoungGC) jvmEvents.get(0));
261+
assertEquals(evt0.getDateTimeStamp(), new DateTimeStamp(75.240));
262+
assertMemoryPoolValues(evt0.getHeap(), 525312, 2013696, 16552, 2013696);
263+
assertDoubleEquals(evt0.getDuration(), 0.1105640);
264+
265+
// 1 - FullGC
266+
assertTrue(jvmEvents.get(1) instanceof FullGC);
267+
FullGC evt1 = ((FullGC) jvmEvents.get(1));
268+
assertEquals(evt1.getDateTimeStamp(), new DateTimeStamp(8357.379));
269+
assertMemoryPoolValues(evt1.getHeap(), 1379524, 2787392, 1236761, 2787392);
270+
assertDoubleEquals(evt1.getDuration(), 43.3665438);
271+
272+
// 2 - InitialMark
273+
assertTrue(jvmEvents.get(2) instanceof InitialMark);
274+
InitialMark evt2 = ((InitialMark) jvmEvents.get(2));
275+
assertEquals(evt2.getDateTimeStamp(), new DateTimeStamp(25293.283));
276+
assertMemoryPoolValues(evt2.getHeap(), 2548071, 3028408, 2548071, 3028408);
277+
assertDoubleEquals(evt2.getDuration(), 0.0743383);
278+
}
279+
280+
@Test
281+
void testCMSGenerationalNoDetailsLines() {
282+
String[] lines = {
283+
"13.563: [GC (Allocation Failure) 886080K->31608K(1986432K), 0.0392109 secs]",
284+
285+
"23.331: [Full GC (Metadata GC Threshold) 17386K->16928K(415232K), 0.0498462 secs]"
286+
// Currently Ignored
287+
//"10.254: [GC (CMS Initial Mark) 460775K(1986432K), 0.0346332 secs]",
288+
//"15.423: [GC (CMS Final Remark) 168951K(1986432K), 0.0388223 secs]"
289+
};
290+
291+
int expectedEventCount = 2;
292+
293+
List<JVMEvent> jvmEvents = feedParser(lines);
294+
assertEquals(jvmEvents.size(), expectedEventCount);
295+
296+
// 0 - PSYoungGen
297+
assertTrue(jvmEvents.get(0) instanceof PSYoungGen);
298+
PSYoungGen evt0 = ((PSYoungGen) jvmEvents.get(0));
299+
assertEquals(evt0.getDateTimeStamp(), new DateTimeStamp(13.563));
300+
assertMemoryPoolValues(evt0.getHeap(), 886080, 1986432, 31608, 1986432);
301+
assertDoubleEquals(evt0.getDuration(), 0.0392109);
302+
303+
// 1 - PSFullGC
304+
assertTrue(jvmEvents.get(1) instanceof FullGC);
305+
FullGC evt1 = ((FullGC) jvmEvents.get(1));
306+
assertEquals(evt1.getDateTimeStamp(), new DateTimeStamp(23.331));
307+
assertMemoryPoolValues(evt1.getHeap(), 17386, 415232, 16928, 415232);
308+
assertDoubleEquals(evt1.getDuration(), 0.0498462);
309+
}
310+
311+
@Test
312+
void testGenerationalDetailsLines() {
313+
String[] lines = {
314+
// 0 - PSFullGC
315+
"2021-12-17T13:34:54.484+0000: 11.445: [Full GC (Metadata GC Threshold) [PSYoungGen: 19070K->0K(475648K)] [ParOldGen: 0K->18752K(1086976K)] 19070K->18752K(1562624K), [Metaspace: 20797K->20797K(1069056K)], 0.3274726 secs] [Times: user=0.11 sys=0.20, real=0.33 secs] ",
316+
317+
// 1 - PSYoungGen
318+
"2021-12-17T13:35:02.874+0000: 19.835: [GC (Metadata GC Threshold) [PSYoungGen: 189709K->8219K(475648K)] 208461K->26971K(1562624K), 0.1027594 secs] [Times: user=0.09 sys=0.10, real=0.10 secs] ",
319+
320+
// 2 - PSYoungGen
321+
"2021-12-17T13:35:24.328+0000: 41.289: [GC (Allocation Failure) [PSYoungGen: 408064K->37889K(475648K)] 442767K->72593K(1562624K), 0.2413144 secs] [Times: user=0.00 sys=0.24, real=0.24 secs] ",
322+
323+
// 3 - PSYoungGen
324+
"2021-12-17T13:36:02.418+0000: 79.379: [GC (System.gc()) [PSYoungGen: 169657K->10443K(423936K)] 329477K->179021K(1510912K), 0.1649078 secs] [Times: user=0.02 sys=0.11, real=0.16 secs] ",
325+
326+
// 4 - SystemGC
327+
"2021-12-17T13:36:02.583+0000: 79.544: [Full GC (System.gc()) [PSYoungGen: 10443K->0K(423936K)] [ParOldGen: 168577K->168475K(1086976K)] 179021K->168475K(1510912K), [Metaspace: 119955K->118885K(1155072K)], 1.2929194 secs] [Times: user=0.98 sys=0.25, real=1.29 secs] ",
328+
329+
// 5 - PSFullGC
330+
"2021-12-17T14:58:05.098+0000: 5002.059: [Full GC (Ergonomics) [PSYoungGen: 60759K->0K(414208K)] [ParOldGen: 974100K->1024865K(1086976K)] 1034860K->1024865K(1501184K), [Metaspace: 154915K->154915K(1187840K)], 0.7945447 secs] [Times: user=0.68 sys=0.06, real=0.79 secs] "
331+
};
332+
333+
int expectedEventCount = 6;
334+
335+
List<JVMEvent> jvmEvents = feedParser(lines);
336+
assertEquals(jvmEvents.size(), expectedEventCount);
337+
338+
// 0 - PSFullGC
339+
assertTrue(jvmEvents.get(0) instanceof PSFullGC);
340+
PSFullGC evt0 = ((PSFullGC) jvmEvents.get(0));
341+
assertEquals(evt0.getDateTimeStamp(), new DateTimeStamp("2021-12-17T13:34:54.484+0000", 11.445));
342+
assertEquals(evt0.getGCCause(), GCCause.METADATA_GENERATION_THRESHOLD);
343+
// Memory Pools
344+
assertMemoryPoolValues(evt0.getHeap(), 19070, 1562624, 18752, 1562624);
345+
assertMemoryPoolValues(evt0.getYoung(), 19070, 475648, 0, 475648);
346+
assertMemoryPoolValues(evt0.getTenured(), 0, 1086976, 18752, 1086976);
347+
assertMemoryPoolValues(evt0.getPermOrMetaspace(), 20797, 1069056, 20797, 1069056);
348+
assertDoubleEquals(evt0.getDuration(), 0.3274726);
349+
assertCPUSummaryValues(evt0.getCpuSummary(), 0.11, 0.20, 0.33);
350+
351+
// 1 - PSYoungGen
352+
assertTrue(jvmEvents.get(1) instanceof PSYoungGen);
353+
PSYoungGen evt1 = ((PSYoungGen) jvmEvents.get(1));
354+
assertEquals(evt1.getDateTimeStamp(), new DateTimeStamp("2021-12-17T13:35:02.874+0000", 19.835));
355+
assertEquals(evt1.getGCCause(), GCCause.METADATA_GENERATION_THRESHOLD);
356+
// Memory Pools
357+
assertMemoryPoolValues(evt1.getHeap(), 208461, 1562624, 26971, 1562624);
358+
assertMemoryPoolValues(evt1.getYoung(), 189709, 475648, 8219, 475648);
359+
assertDoubleEquals(evt1.getDuration(), 0.1027594);
360+
assertCPUSummaryValues(evt1.getCpuSummary(), 0.09, 0.10, 0.10);
361+
362+
// 2 - PSYoungGen
363+
assertTrue(jvmEvents.get(2) instanceof PSYoungGen);
364+
PSYoungGen evt2 = ((PSYoungGen) jvmEvents.get(2));
365+
assertEquals(evt2.getDateTimeStamp(), new DateTimeStamp("2021-12-17T13:35:24.328+0000", 41.289));
366+
assertEquals(evt2.getGCCause(), GCCause.ALLOCATION_FAILURE);
367+
// Memory Pools
368+
assertMemoryPoolValues(evt2.getHeap(), 442767, 1562624, 72593, 1562624);
369+
assertMemoryPoolValues(evt2.getYoung(), 408064, 475648, 37889, 475648);
370+
assertDoubleEquals(evt2.getDuration(), 0.2413144);
371+
assertCPUSummaryValues(evt2.getCpuSummary(), 0.0, 0.24, 0.24);
372+
373+
// 3 - PSYoungGen (SystemGC)
374+
assertTrue(jvmEvents.get(3) instanceof PSYoungGen);
375+
PSYoungGen evt3 = ((PSYoungGen) jvmEvents.get(3));
376+
assertEquals(evt3.getDateTimeStamp(), new DateTimeStamp("2021-12-17T13:36:02.418+0000", 79.379));
377+
assertEquals(evt3.getGCCause(), GCCause.JAVA_LANG_SYSTEM);
378+
// Memory Pools
379+
assertMemoryPoolValues(evt3.getHeap(), 329477, 1510912, 179021, 1510912);
380+
assertMemoryPoolValues(evt3.getYoung(), 169657, 423936, 10443, 423936);
381+
assertDoubleEquals(evt3.getDuration(), 0.1649078);
382+
assertCPUSummaryValues(evt3.getCpuSummary(), 0.02, 0.11, 0.16);
383+
384+
// 4 - PSFullGC (SystemGC)
385+
assertTrue(jvmEvents.get(4) instanceof SystemGC);
386+
SystemGC evt4 = ((SystemGC) jvmEvents.get(4));
387+
assertEquals(evt4.getDateTimeStamp(), new DateTimeStamp("2021-12-17T13:36:02.583+0000", 79.544));
388+
assertEquals(evt4.getGCCause(), GCCause.JAVA_LANG_SYSTEM);
389+
// Memory Pools
390+
assertMemoryPoolValues(evt4.getHeap(), 179021, 1510912, 168475, 1510912);
391+
assertMemoryPoolValues(evt4.getYoung(), 10443, 423936, 0, 423936);
392+
assertMemoryPoolValues(evt4.getTenured(), 168577, 1086976, 168475, 1086976);
393+
assertMemoryPoolValues(evt4.getPermOrMetaspace(), 119955, 1155072, 118885, 1155072);
394+
assertDoubleEquals(evt4.getDuration(), 1.2929194);
395+
assertCPUSummaryValues(evt4.getCpuSummary(), 0.98, 0.25, 1.29);
396+
397+
// 5 - PSFullGC (Ergonomics)
398+
assertTrue(jvmEvents.get(5) instanceof PSFullGC);
399+
PSFullGC evt5 = ((PSFullGC) jvmEvents.get(5));
400+
assertEquals(evt5.getDateTimeStamp(), new DateTimeStamp("2021-12-17T14:58:05.098+0000", 5002.059));
401+
assertEquals(evt5.getGCCause(), GCCause.ADAPTIVE_SIZE_POLICY);
402+
// Memory Pools
403+
assertMemoryPoolValues(evt5.getHeap(), 1034860, 1501184, 1024865, 1501184);
404+
assertMemoryPoolValues(evt5.getYoung(), 60759, 414208, 0, 414208);
405+
assertMemoryPoolValues(evt5.getTenured(), 974100, 1086976, 1024865, 1086976);
406+
assertMemoryPoolValues(evt5.getPermOrMetaspace(), 154915, 1187840, 154915, 1187840);
407+
assertDoubleEquals(evt5.getDuration(), 0.7945447);
408+
assertCPUSummaryValues(evt5.getCpuSummary(), 0.68, 0.06, 0.79);
409+
}
410+
411+
217412
@Override
218413
protected Diarizer diarizer() {
219414
return new PreUnifiedDiarizer();

0 commit comments

Comments
 (0)