G1 activity time incorrect

[static-max]

When connected to a process that uses G1 as GC, most CPU usage of the garbage collector is not counted as GC activity.

I see heavy CPU usage spikes in the chart when the garbage collector is kicking in. However, there is no to little GC activity in the chart.

Around the last spike:

2019-10-30 13:04:14.372 TRACE 1164 ---
[1731.846s][info   ][gc,start      ] GC(309) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[1731.846s][info   ][gc,task       ] GC(309) Using 8 workers of 8 for evacuation
[1731.880s][info   ][gc,phases     ] GC(309)   Pre Evacuate Collection Set: 0.3ms
[1731.880s][info   ][gc,phases     ] GC(309)   Evacuate Collection Set: 10.3ms
[1731.880s][info   ][gc,phases     ] GC(309)   Post Evacuate Collection Set: 22.0ms
[1731.880s][info   ][gc,phases     ] GC(309)   Other: 1.0ms
[1731.880s][info   ][gc,heap       ] GC(309) Eden regions: 566->0(876)
[1731.880s][info   ][gc,heap       ] GC(309) Survivor regions: 12->34(117)
[1731.880s][info   ][gc,heap       ] GC(309) Old regions: 738->738
[1731.880s][info   ][gc,heap       ] GC(309) Archive regions: 0->0
[1731.880s][info   ][gc,heap       ] GC(309) Humongous regions: 152->46
[1731.880s][info   ][gc,metaspace  ] GC(309) Metaspace: 84190K->84190K(1124352K)
[1731.880s][info   ][gc            ] GC(309) Pause Young (Concurrent Start) (G1 Humongous Allocation) 2932M->1633M(3954M) 33.918ms
[1731.880s][info   ][gc,cpu        ] GC(309) User=0.16s Sys=0.09s Real=0.03s
[1731.880s][info   ][gc            ] GC(310) Concurrent Cycle
[1731.880s][info   ][gc,marking    ] GC(310) Concurrent Clear Claimed Marks
[1731.880s][info   ][gc,marking    ] GC(310) Concurrent Clear Claimed Marks 0.237ms
[1731.880s][info   ][gc,marking    ] GC(310) Concurrent Scan Root Regions
[1731.887s][info   ][gc,marking    ] GC(310) Concurrent Scan Root Regions 6.537ms
[1731.887s][info   ][gc,marking    ] GC(310) Concurrent Mark (1731.887s)
[1731.887s][info   ][gc,marking    ] GC(310) Concurrent Mark From Roots
[1731.887s][info   ][gc,task       ] GC(310) Using 2 workers of 2 for marking
2019-10-30 13:04:14.488 DEBUG 1164 ---
2019-10-30 13:04:16.035 DEBUG 1164 ---
[1733.723s][info   ][gc,marking    ] GC(310) Concurrent Mark From Roots 1836.109ms
[1733.723s][info   ][gc,marking    ] GC(310) Concurrent Preclean
[1733.723s][info   ][gc,marking    ] GC(310) Concurrent Preclean 0.171ms
[1733.723s][info   ][gc,marking    ] GC(310) Concurrent Mark (1731.887s, 1733.723s) 1836.327ms
[1733.723s][info   ][gc,start      ] GC(310) Pause Remark
[1733.730s][info   ][gc,stringtable] GC(310) Cleaned string table, strings: 1266786 processed, 0 removed
[1733.731s][info   ][gc            ] GC(310) Pause Remark 1693M->1693M(3954M) 7.230ms
[1733.731s][info   ][gc,cpu        ] GC(310) User=0.00s Sys=0.00s Real=0.01s
2019-10-30 13:04:16.873 DEBUG 1164 ---
[1733.731s][info   ][gc,marking    ] GC(310) Concurrent Rebuild Remembered Sets
[1734.663s][info   ][gc,marking    ] GC(310) Concurrent Rebuild Remembered Sets 932.446ms
[1734.663s][info   ][gc,start      ] GC(310) Pause Cleanup
[1734.664s][info   ][gc            ] GC(310) Pause Cleanup 1738M->1738M(3954M) 0.879ms
[1734.664s][info   ][gc,cpu        ] GC(310) User=0.00s Sys=0.00s Real=0.00s
[1734.664s][info   ][gc,marking    ] GC(310) Concurrent Cleanup for Next Mark
[1734.669s][info   ][gc,marking    ] GC(310) Concurrent Cleanup for Next Mark 4.648ms
[1734.669s][info   ][gc            ] GC(310) Concurrent Cycle 2788.981ms

Also the times in the "Visual GC" tab for "GC Time" and "Eden Space" are the same.

JVM parameters: -Xmx8G -XX:+PrintGC -XX:+PrintGCDetails

VisualVM: 1.4.3, 1.4.4

Application tested on JVMs: jdk-12.0.1.12-hotspot, jdk-13+33

Selecting a different GC (-XX:+UseParallelOldGC) shows correct graph and times.

[thurka]

Thanks for the detailed report. I am however not able to find suitable java application, where this can be reproduced. Is there a particular application I can use to reproduce it?

[static-max]

The screenshots are from an internal tool that does a lot of larger (1MB) string and byte array crunching, data compression and networking. I'm not sure if that helps, right now I cannot make it public.