RFR: 8350313: Include timings for leaving safepoint in safepoint logging
Xiaolong Peng
xpeng at openjdk.org
Mon Feb 24 23:52:04 UTC 2025
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
-------------
Commit messages:
- 8350313: Include timings for leaving safepoint in safepoint logging
Changes: https://git.openjdk.org/jdk/pull/23756/files
Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=23756&range=00
Issue: https://bugs.openjdk.org/browse/JDK-8350313
Stats: 14 lines in 2 files changed: 11 ins; 0 del; 3 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
More information about the hotspot-runtime-dev
mailing list