RFR: 8336742: Shenandoah: Add more verbose logging/stats for mark termination attempts [v4]
Neethu Prasad
nprasad at openjdk.org
Wed Aug 7 13:19:12 UTC 2024
> **Revision 2 Notes**
> 1. Added time spent on handshaking all threads requesting them to flush their SATB buffers as part of GC stats.
> 2. As mentioned in PR feedback, will raise separate PR to adding logging in ShenandoahTimingsTracker.
>
> **Revision 1 Notes**
> This PR adds the following
> 1. info logging on number of SATB flush attempts
> 3. total time spend on handshaking all threads requesting them to flush their SATB buffers.
>
> As suggested by William in [JDK-8336742 ](https://bugs.openjdk.org/browse/JDK-83367420), we can use handshake logging to get time spend and other stats for each handshake.
>
> [4.515s][info][handshake ] Handshake "Shenandoah Flush SATB Handshake", Targeted threads: 1036, Executed by requesting thread: 1035, Total completion time: 597004 ns
> [4.517s][info][handshake ] Handshake "Shenandoah Flush SATB Handshake", Targeted threads: 1036, Executed by requesting thread: 1033, Total completion time: 207402 ns
>
>
> **Testing**
> 1. tier1, tier2 and hotspot_gc_shenandoah tests.
> 2. **-Xlog:gc+stats=info**
>
>
> [37.087s][info][gc,stats] CMR: VM Strong Roots 413 us, workers (us): 64, 57, 52, 47, 38, 31, 30, 25, 20, 21, 17, 10, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---,
> [37.087s][info][gc,stats] CMR: CLDG Roots 449 us, workers (us): 4, ---, ---, 406, ---, 15, ---, 4, 4, ---, ---, 17, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---,
> [37.087s][info][gc,stats] Concurrent Marking 5002 us
> [37.087s][info][gc,stats] SATB Flush Rendezvous 1748 us
> [37.087s][info][gc,stats] Pause Final Mark (G) 57272 us
> [37.087s][info][gc,stats] Pause Final Mark (N) 56985 us
> [37.087s][info][gc,stats] Finish Mark 387 us
> [37.087s][info][gc,stats] Update Region States 109 us
> [37.087s][info][gc,stats] Choose Collection Set 56395 us
> [37.087s][info][gc,stats] Rebuild Free Set 40 us
>
>
> on app termination
>
>
> [40.640s][info][gc,stats] Concurrent Reset = 0.914 s (a = 65255 us) (n = 14) (lvls, us = 54883, 55859, 63867, 65234, 97096)
> [40.640s][info][gc,stats] Pause Init Mark (G) = 1.755 s (a = 125380 us) (n = 14) (lvls, us = 119141, 123047, 125000, 125000, 128042)
> [40.640s][info][gc,stats] Pause Init Mark (N) = 1.697 s (a = 121241 us) (n = 14) (lvls, us = 117188, 119141, 121094, 121094, 123880)
> ...
Neethu Prasad has updated the pull request incrementally with one additional commit since the last revision:
Address feedback on code style
-------------
Changes:
- all: https://git.openjdk.org/jdk/pull/20318/files
- new: https://git.openjdk.org/jdk/pull/20318/files/a7c0514a..9649c2ca
Webrevs:
- full: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=03
- incr: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=02-03
Stats: 5 lines in 3 files changed: 1 ins; 2 del; 2 mod
Patch: https://git.openjdk.org/jdk/pull/20318.diff
Fetch: git fetch https://git.openjdk.org/jdk.git pull/20318/head:pull/20318
PR: https://git.openjdk.org/jdk/pull/20318
More information about the shenandoah-dev
mailing list