Missing gc time in zgc generational logging

[Erik Osterlund]

Hi Mike,

All GC logs for all GCs show the time spent by the GC operation in a safepoint, while the safepoint logging includes details about time to safepoint etc. While this is indeed the same for all GCs, it might be worth noting that the time to safepoint includes the time it takes to shut down other GC threads as well as mutator threads. In particular, if there is a concurrent old generation collection going on when synchronizing a young mark start pause, we will first suspend those old generation GC threads, before we start to shut down the mutator threads. In a way, that can make the time to safepoint numbers look a bit inflated, as we are not really interrupting the mutator threads until after the GC threads have been synchronized. This anomaly never showed up with single generation ZGC, as it didn’t have any “other” generation workers to shut down when scheduling safepoints, and this part was a no-op.

Maybe it would be nice to distinguish how long time is spent on synchronizing the Java threads specifically, excluding the time for waiting for GC threads.

/Erik

> On 8 Jan 2024, at 15:12, Mike Millson <mmillson at redhat.com> wrote:
> 
> There seems to be a lot of missing gc time in the jdk21 zgc generational logging.
> 
> Following is an example (complete log attached).
> 
> The gc time below is .234ms, and the safepoint is 2.7ms (1900085+806967+4204/10^6).
> 
> It's over an order of magnitude off.
> 
> [2023-12-12T10:20:45.260+0200][info][gc,phases   ] GC(34) y: Pause Mark Start 0.234ms
> [2023-12-12T10:20:45.260+0200][info][safepoint   ] Safepoint "ZMarkStartYoung", Time since last: 9642266719 ns, Reaching safepoint: 1900085 ns, Cleanup: 4204 ns, At safepoint: 806967 ns, Total: 2711256 ns
> 
> Thank you,
> Mike
> <gc.log>