Missing gc time in zgc generational logging

[Mike Millson]

Hi Erik,

I think what you are referring to is what other collectors included in
"Other" time, is that right?

For example, in the G1 logging below, the "Other: 0.1ms" is time spent
outside of garbage collection, and the Safepoint time is equal to the GC
time (4.858ms) plus this "Other" time (0.1ms).

In my experience, this "Other" time with other collectors is
zero/negligible except when there is some performance issue (e.g. an I/O
delay preventing a timely GC log write from one line to the next).

It seems like with ZGC, it's normal (not an indicator of a performance
issue) to have this "Other" time, is that correct?

>From my perspective, it's nice to be able to relate the GC times to the
safepoint times, so I would be in favor of having ZGC logging that allows
that. As it stands now, when looking at max pause and throughput, I think I
can only trust the Safepoint logging because there is missing time in the
GC logging.

~~~
[0.109s][info][safepoint    ] Entering safepoint region:
G1CollectForAllocation
[0.109s][info][gc,start     ] GC(1) Pause Young (Concurrent Start) (G1
Evacuation Pause)
[0.109s][info][gc,task      ] GC(1) Using 2 workers of 4 for evacuation
[0.114s][info][gc,phases    ] GC(1)   Pre Evacuate Collection Set: 0.0ms
[0.114s][info][gc,phases    ] GC(1)   Evacuate Collection Set: 4.6ms
[0.114s][info][gc,phases    ] GC(1)   Post Evacuate Collection Set: 0.1ms
[0.114s][info][gc,phases    ] GC(1)   Other: 0.1ms
[0.114s][info][gc,heap      ] GC(1) Eden regions: 1->0(1)
[0.114s][info][gc,heap      ] GC(1) Survivor regions: 1->1(1)
[0.114s][info][gc,heap      ] GC(1) Old regions: 2->2
[0.114s][info][gc,heap      ] GC(1) Humongous regions: 0->0
[0.114s][info][gc,metaspace ] GC(1) Metaspace: 879K->879K(1056768K)
[0.114s][info][gc           ] GC(1) Pause Young (Concurrent Start) (G1
Evacuation Pause) 2M->1M(5M) 4.858ms
[0.114s][info][gc,cpu       ] GC(1) User=0.01s Sys=0.00s Real=0.01s
[0.114s][info][safepoint    ] Leaving safepoint region
[0.114s][info][safepoint    ] Total time for which application threads were
stopped: 0.0049236 seconds, Stopping threads took: 0.0000050 seconds
~~~

Thank you,
Mike

On Mon, Jan 8, 2024 at 10:25 AM Erik Osterlund <erik.osterlund at oracle.com>
wrote:

> 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>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/zgc-dev/attachments/20240108/fe2efd79/attachment.htm>