microsoft / gctoolkit

Tool for parsing GC logs
https://github.com/microsoft/gctoolkit
MIT License
1.25k stars 153 forks source link

GCToolKit cannot parse `G1Young` event from JDK8's gc log. #357

Open BurryPotter opened 5 months ago

BurryPotter commented 5 months ago

Describe the bug I first used JDK 8 and set -XX:+UseG1GC option to run a program, and exported the GC log (I will provide the link to the log file later). Then, when using GCToolKit to parse the log, I found that it could only parse some of the G1 events, such as ConcurrentRootRegionScan, ConcurrentMark, etc. But it could not parse G1Young and other PauseEvents.

To Reproduce Steps to reproduce the behavior:

  1. Download the reproduce code and gc log
  2. Compile and run the program. This program will parse the events from the gc log ('g1_8.log'), and print their GarbageCollectionTypes.
  3. Check the output of gc log parsing.

Expected behavior Print a series of events including G1Young

Actually behavior Print a series of events like this:

ConcurrentRootRegionScan
ConcurrentMark
G1GCRemark
G1GCCleanup
ConcurrentRootRegionScan
G1GCConcurrentMark
ConcurrentRootRegionScan
ConcurrentMark
Bluetopia commented 5 months ago

I may have a fix for a similar issue (#352) and wanted to see if it happens to handle your situation as well, but I can't download your sample GC log. Can you attach the gc log here so I can check?

BurryPotter commented 5 months ago

Here is the GC log.

Java HotSpot(TM) 64-Bit Server VM (25.331-b09) for windows-amd64 JRE (1.8.0_331-b09), built on Mar 10 2022 03:14:38 by "java_re" with MS VC++ 15.9 (VS2017)
Memory: 4k page, physical 16533900k(4409648k free), swap 29641100k(7540308k free)
CommandLine flags: -XX:InitialHeapSize=264542400 -XX:MaxHeapSize=1073741824 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation -XX:+VerifyBeforeGC 
0.086: [GC pause (G1 Humongous Allocation) (young) (initial-mark) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 69M->69M(254M), 0.0362183 secs]
0.219: [GC concurrent-root-region-scan-start]
0.220: [GC concurrent-root-region-scan-end, 0.0005514 secs]
0.220: [GC concurrent-mark-start]
0.222: [GC concurrent-mark-end, 0.0021289 secs]
0.222: [GC remark, 0.0034649 secs]
0.226: [GC cleanup 347M->347M(590M), 0.0025024 secs]
0.322: [GC pause (G1 Humongous Allocation) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 602M->602M(1024M), 0.0143577 secs]
0.337: [GC pause (G1 Evacuation Pause) (young) (initial-mark) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
-- 603M->603M(1024M), 0.0155159 secs]
0.352: [GC concurrent-root-region-scan-start]
0.352: [GC concurrent-root-region-scan-end, 0.0000039 secs]
0.352: [GC concurrent-mark-start]
0.356: [GC pause (G1 Evacuation Pause) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 603M->603M(1024M), 0.0142141 secs]
0.370: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 603M->603M(1024M), 0.0147102 secs]
0.385: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 603M->603M(1024M), 0.0139963 secs]
0.399: [GC pause (G1 Evacuation Pause) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 603M->603M(1024M), 0.0129203 secs]
0.412: [GC concurrent-mark-abort]
0.412: [GC pause (G1 Evacuation Pause) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 603M->603M(1024M), 0.0110956 secs]
0.423: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 603M->625K(8192K), 0.0492972 secs]
0.473: [GC pause (G1 Humongous Allocation) (young) (initial-mark) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 707K->629K(16M), 0.0082750 secs]
0.482: [GC concurrent-root-region-scan-start]
0.482: [GC concurrent-root-region-scan-end, 0.0001604 secs]
0.482: [GC concurrent-mark-start]
0.482: [GC concurrent-mark-end, 0.0004756 secs]
0.483: [GC remark, 0.0020766 secs]
0.485: [GC cleanup 8501K->8501K(16M), 0.0007410 secs]
0.703: [GC pause (G1 Humongous Allocation) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
-- 602M->602M(1024M), 0.0154597 secs]
0.719: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 602M->601M(1024M), 0.0164509 secs]
0.735: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 601M->601M(1024M), 0.0137834 secs]
0.750: [GC pause (G1 Humongous Allocation) (young) (initial-mark) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 602M->601M(1024M), 0.0152290 secs]
0.765: [GC concurrent-root-region-scan-start]
0.765: [GC concurrent-root-region-scan-end, 0.0000036 secs]
0.765: [GC concurrent-mark-start]
0.765: [GC pause (G1 Humongous Allocation) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 601M->601M(1024M), 0.0126219 secs]
0.778: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 601M->624K(8192K), 0.0478035 secs]
0.826: [GC concurrent-mark-abort]
0.826: [GC pause (G1 Humongous Allocation) (young) (initial-mark) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 4802K->4723K(16M), 0.0096633 secs]
0.836: [GC concurrent-root-region-scan-start]
0.836: [GC concurrent-root-region-scan-end, 0.0000478 secs]
0.836: [GC concurrent-mark-start]
0.838: [GC concurrent-mark-end, 0.0018626 secs]
0.838: [GC remark, 0.0013151 secs]
0.840: [GC cleanup 11M->11M(20M), 0.0006853 secs]
1.077: [GC pause (G1 Humongous Allocation) (young) VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
-- 602M->602M(1024M), 0.0164034 secs]
1.094: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 602M->601M(1024M), 0.0153615 secs]
1.109: [Full GC (Allocation Failure)  VerifyBeforeGC:[Verifying Threads Heap Roots HeapRegionSets HeapRegions RemSet SymbolTable StringTable CodeCache SystemDictionary MetaspaceAux JNIHandles C-heap CodeCache Oops ]
 601M->601M(1024M), 0.0154743 secs]
jlittle-ptc commented 5 months ago

No such luck. There are a lot of advanced flags configured in this file, whereas the change I made was for a relatively simple use case that was broken.