RFR: 8350314: Shenandoah: Capture thread state sync times in GC timings
Xiaolong Peng
xpeng at openjdk.org
Tue Feb 25 22:47:16 UTC 2025
The change is to improve the observability of Shenandoah GC, basically there are two changes for Shenandoah GC timings in this PR:
1. Net GC pause timings include the time to propagate GC state to Java threads
2. Add new timing "Propagate GC state" in Shenandoah GC timing logs
With the change, the new GC timing log will be like:
[11.056s][info][gc,stats ] Concurrent Reset 89 us
[11.056s][info][gc,stats ] Pause Init Mark (G) 257 us
[11.056s][info][gc,stats ] Pause Init Mark (N) 17 us
[11.056s][info][gc,stats ] Update Region States 3 us
[11.056s][info][gc,stats ] Propagate GC state 1 us
[11.056s][info][gc,stats ] Concurrent Mark Roots 232 us, parallelism: 1.96x
[11.056s][info][gc,stats ] CMR: <total> 456 us
[11.056s][info][gc,stats ] CMR: Thread Roots 429 us, workers (us): 139, 148, 142, ---, ---, ---,
[11.057s][info][gc,stats ] CMR: VM Strong Roots 11 us, workers (us): 8, 3, 0, ---, ---, ---,
[11.057s][info][gc,stats ] CMR: CLDG Roots 16 us, workers (us): 16, ---, ---, ---, ---, ---,
[11.057s][info][gc,stats ] Concurrent Marking 1304 us, parallelism: 2.33x
[11.057s][info][gc,stats ] CM: <total> 3043 us
[11.057s][info][gc,stats ] CM: Parallel Mark 3043 us, workers (us): 1023, 1017, 1003, ---, ---, ---,
[11.057s][info][gc,stats ] Flush SATB 204 us
[11.057s][info][gc,stats ] Pause Final Mark (G) 865 us
[11.057s][info][gc,stats ] Pause Final Mark (N) 234 us
[11.057s][info][gc,stats ] Finish Mark 129 us, parallelism: 0.01x
[11.057s][info][gc,stats ] Propagate GC state 2 us
[11.057s][info][gc,stats ] Update Region States 12 us
[11.057s][info][gc,stats ] Choose Collection Set 25 us
[11.057s][info][gc,stats ] Rebuild Free Set 29 us
[11.057s][info][gc,stats ] Concurrent Weak References 67 us, parallelism: 0.25x
[11.057s][info][gc,stats ] CWRF: <total> 17 us
[11.057s][info][gc,stats ] CWRF: Weak References 17 us, workers (us): 15, 1, 0, ---, ---, ---,
[11.057s][info][gc,stats ] Concurrent Weak Roots 413 us
[11.057s][info][gc,stats ] Roots 203 us, parallelism: 1.95x
[11.057s][info][gc,stats ] CWR: <total> 396 us
[11.057s][info][gc,stats ] CWR: Code Cache Roots 295 us, workers (us): 90, 96, 109, ---, ---, ---,
[11.057s][info][gc,stats ] CWR: VM Weak Roots 100 us, workers (us): 48, 37, 14, ---, ---, ---,
[11.057s][info][gc,stats ] CWR: CLDG Roots 2 us, workers (us): ---, ---, 2, ---, ---, ---,
[11.058s][info][gc,stats ] Rendezvous 197 us
[11.058s][info][gc,stats ] Concurrent Cleanup 35 us
[11.058s][info][gc,stats ] Concurrent Class Unloading 486 us
[11.058s][info][gc,stats ] Unlink Stale 398 us
[11.058s][info][gc,stats ] System Dictionary 5 us
[11.058s][info][gc,stats ] Weak Class Links 0 us
[11.058s][info][gc,stats ] Code Roots 391 us
[11.058s][info][gc,stats ] Rendezvous 69 us
[11.058s][info][gc,stats ] Purge Unlinked 4 us
[11.058s][info][gc,stats ] Code Roots 0 us
[11.058s][info][gc,stats ] CLDG 3 us
[11.058s][info][gc,stats ] Pause Final Roots (G) 272 us
[11.058s][info][gc,stats ] Pause Final Roots (N) 18 us
[11.058s][info][gc,stats ] Propagate GC state 3 us
### Test
- [x] make test TEST=hotspot_gc_shenandoah
-------------
Commit messages:
- Log time to propagate GC state
- 8350314: Shenandoah: Capture thread state sync times in GC timings
Changes: https://git.openjdk.org/jdk/pull/23759/files
Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=23759&range=00
Issue: https://bugs.openjdk.org/browse/JDK-8350314
Stats: 47 lines in 5 files changed: 40 ins; 7 del; 0 mod
Patch: https://git.openjdk.org/jdk/pull/23759.diff
Fetch: git fetch https://git.openjdk.org/jdk.git pull/23759/head:pull/23759
PR: https://git.openjdk.org/jdk/pull/23759
More information about the hotspot-gc-dev
mailing list