RFR: 8350313: Include timings for leaving safepoint in safepoint logging [v3]

[Xiaolong Peng]

On Tue, 25 Feb 2025 17:03:42 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
>
> Xiaolong Peng has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Renames

Thank you all for the reviews!

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

PR Comment: https://git.openjdk.org/jdk/pull/23756#issuecomment-2685731150