Integrated: 8350313: Include timings for leaving safepoint in safepoint logging

[Xiaolong Peng]

On Mon, 24 Feb 2025 20:48:25 GMT, Xiaolong Peng <xpeng at openjdk.org> wrote:

> Hi there,
> Please help with reviewing the PR. The change is to improve the observability of timings of safepoints. We have a production use case where leaving the safepoint introduced a significant latency, mostly due to VMThread getting de-scheduled, more details can be find in JBS bug [JDK-8350324](https://bugs.openjdk.org/browse/JDK-8350324). 
> 
> Current safepoint log is like:
> 
> [3.427s][info][gc       ] GC(6) Pause Final Mark (unload classes) 0.201ms
> [3.428s][info][safepoint] Safepoint "ShenandoahFinalMarkStartEvac", Time since last: 2463125 ns, Reaching safepoint: 14958 ns, At safepoint: 410834 ns, Total: 425792 ns
> 
> 
> 
> The "At safepoint" time include the time to evaluate the VM operation and the time to leave safepoint(cleanup, disarm WaitBarrier..etc.), from safepoint log we don't really know how much time it takes to leave safepoint. 
> 
> As proposed in [JDK-8350313](https://bugs.openjdk.org/browse/JDK-8350313), we think a "Leaving safepoint" counter just like "Reaching safepoint" could be nice to have. It comes with the symmetry advantage with "Reaching safepoint" counter. "Leaving safepoint" measures the time spent in safepoint machinery from the "finishing side". And, it more clearly captures the transitional state where some threads might be still at safepoint, and some have already unparked, like "Reaching safepoint".
> 
> With the new "Leaving safepoint" counter, the log will be like:
> 
> [17.764s][info][gc       ] GC(84) Pause Final Mark (unload classes) 0.179ms
> [17.764s][info][safepoint] Safepoint "ShenandoahFinalMarkStartEvac", Time since last: 3340792 ns, Reaching safepoint: 31250 ns, At safepoint: 187958 ns, Leaving safepoint: 177833 ns, Total: 397041 ns
> 
> 
> ### Tests
> - [x] Verified the new safepoint log
> - [x] Tier 2

This pull request has now been integrated.

Changeset: 9ec46968
Author:    Xiaolong Peng <xpeng at openjdk.org>
Committer: Aleksey Shipilev <shade at openjdk.org>
URL:       https://git.openjdk.org/jdk/commit/9ec46968fbfddf99a8349cb6903d24b1c2fdaf1d
Stats:     14 lines in 2 files changed: 11 ins; 0 del; 3 mod

8350313: Include timings for leaving safepoint in safepoint logging

Reviewed-by: shade, dholmes

-------------

PR: https://git.openjdk.org/jdk/pull/23756