RFR: 8336742: Shenandoah: Add more verbose logging/stats for mark termination attempts [v5]
Neethu Prasad
nprasad at openjdk.org
Tue Aug 13 16:37:14 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**
>
>
> [4.911s][info][gc,stats] CMR: VM Strong Roots 539 us, workers (us): 102, 89, 89, 79, 46, 40, 40, 25, 24, 1, 2, 2, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---,
> [4.911s][info][gc,stats] CMR: CLDG Roots 461 us, workers (us): 429, 5, 12, 11, 4, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---, ---,
> [4.911s][info][gc,stats] Concurrent Marking 4392 us
> [4.911s][info][gc,stats] Flush SATB 1035 us
> [4.911s][info][gc,stats] Pause Final Mark (G) 2615 us
> [4.912s][info][gc,stats] Pause Final Mark (N) 2339 us
> [4.912s][info][gc,stats] Finish Mark 780 us
> [4.912s][info][gc,stats] Update Region States 109 us
> [4.912s][info][gc,stats] Choose Collection Set 1336 us
> [4.912s][info][gc,stats] Rebuild Free Set 23 us
>
>
> on app termination
>
>
> 4.924s][info][gc,stats] Concurrent Reset = 0.042 s (a = 1846 us) (n = 23) (lvls, us = 1113, 1660, 1895, 2031, 2674)
> [4.924s][info][gc,stats] Pause Init Mark (G) = 0.073 s (a = 3163 us) (n = 23) (lvls, us = 2812, 2949, 3047, 3281, 3790)
> [4.924s][info][gc,stats] Pause Init Mark (N) = 0.065 s (a = 2810 us) (n = 23) (lvls, us = 2578, 2676, 2793, 2793, 3260)
> [4.924s][info]...
Neethu Prasad has updated the pull request incrementally with one additional commit since the last revision:
Rename phase to Flush SATB
-------------
Changes:
- all: https://git.openjdk.org/jdk/pull/20318/files
- new: https://git.openjdk.org/jdk/pull/20318/files/9649c2ca..1609ed50
Webrevs:
- full: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=04
- incr: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=03-04
Stats: 1 line in 1 file changed: 0 ins; 0 del; 1 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 hotspot-gc-dev
mailing list