microsoft
[Question] Why GenerationalHeapParser ignored CMS Concurrent Event and Remark but only recognized InitialMark?
Describe the bug As the title describes. The relate code is here
To Reproduce Steps to reproduce the behavior:
For such a log, i want to extract the InitMark, ConcurrentEvent and Remark. When I use both EventSource.GENERATIONAL and EventSource.CMS_PREUNIFIED, the InitMark was extract twice, is it some reason special?
Java HotSpot(TM) 64-Bit Server VM (25.192-b12) for linux-amd64 JRE (1.8.0_192-b12), built on Oct 6 2018 06:46:09 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 98947364k(11432988k free), swap 16383996k(15611232k free)
CommandLine flags: -XX:CMSInitiatingOccupancyFraction=70 -XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/logs/hubble-web-v4/ -XX:InitialHeapSize=4294967296 -XX:MaxHeapSize=4294967296 -XX:MaxTenuringThreshold=10 -XX:NewRatio=2 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=3 -XX:-UseAdaptiveSizePolicy -XX:+UseCMSCompactAtFullCollection -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
2023-12-28T15:57:13.074+0800: 3.205: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(2796224K)] 53575K(3914688K), 0.0045636 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
2023-12-28T15:57:13.079+0800: 3.209: [CMS-concurrent-mark-start]
2023-12-28T15:57:13.079+0800: 3.210: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-12-28T15:57:13.079+0800: 3.210: [CMS-concurrent-preclean-start]
2023-12-28T15:57:13.085+0800: 3.215: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.06 sys=0.01, real=0.01 secs]
2023-12-28T15:57:13.085+0800: 3.216: [CMS-concurrent-abortable-preclean-start]
2023-12-28T15:57:13.809+0800: 3.940: [CMS-concurrent-abortable-preclean: 0.443/0.724 secs] [Times: user=3.94 sys=0.14, real=0.72 secs]
2023-12-28T15:57:13.809+0800: 3.940: [GC (CMS Final Remark) [YG occupancy: 560011 K (1118464 K)]
2023-12-28T15:57:13.809+0800: 3.940: [Rescan (parallel) , 0.0197664 secs]
2023-12-28T15:57:13.829+0800: 3.960: [weak refs processing, 0.0000455 secs]
2023-12-28T15:57:13.829+0800: 3.960: [class unloading, 0.0066301 secs]
2023-12-28T15:57:13.836+0800: 3.967: [scrub symbol table, 0.0046419 secs]
2023-12-28T15:57:13.841+0800: 3.971: [scrub string table, 0.0006346 secs][1 CMS-remark: 0K(2796224K)] 560011K(3914688K), 0.0328288 secs] [Times: user=0.45 sys=0.01, real=0.03 secs]
Expected behavior A clear and concise description of what you expected to happen.
GCToolkit version:
- 3.0.4
Additional context no
This is a bug as something must have gotten lost. I'll make sure this is corrected.
@kcpeppe Sorry to bother you. Do you have plan to fix the issue? If not, maybe i could provide some help. Removing CMSInitialMark from GenerationalHeapParser is the simplest way, right?
I'm currently looking at this along with another parsing bug that I've discovered.
@loyispa I've reproduced the problem in a test which I'll check that in (branch 318). The issue is that EventSource.GENERATIONAL and EventSource.CMS_PREUNIFIED both produce an InitialMark and a Remark event. This is because these event are pause events and need to be treated as such by queries that process GENERATIONAL events. However, these events are also an integral part of the CMS cycle so they do belong in both parsers.
The difference between the unified and pre-unified handling of CMS is that in the unified log parser, the generational parser manages the CMS cycle. This prevents the duplication problem. Thus the solution here is to merge the CMS parser into the generational parser. The trick in this is to ensure time order. All events are streamed in the order of time in which they started.
I was going to suggest a work-around but now I see that my work-around won't work as the remark start times need to be corrected. Again, the best way to correct this is to combine the parsers.
A second work around would be to process GENERATIONAL separately from CMS_PREUNIFIED. You could combine the results after the fact. This complication could be reversed once the compilers are merged.
First cut at merging CMSParser into GenerationalHeapParser. To use this replace EventSource.CMS_PREUNIFIED with EventSource.GENERATIONAL. Sorry, I have some issues with my github account that is preventing me from pushing a branch. The branch is here @ https://github.com/kcpeppe/gctoolkit/tree/318
@loyispa