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

[Xiaolong Peng]

> 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

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

Changes:
  - all: https://git.openjdk.org/jdk/pull/23756/files
  - new: https://git.openjdk.org/jdk/pull/23756/files/e2bbd440..166ba0e0

Webrevs:
 - full: https://webrevs.openjdk.org/?repo=jdk&pr=23756&range=01
 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=23756&range=00-01

  Stats: 7 lines in 2 files changed: 0 ins; 0 del; 7 mod
  Patch: https://git.openjdk.org/jdk/pull/23756.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/23756/head:pull/23756

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