RFR: 8336742: Shenandoah: Add more verbose logging/stats for mark termination attempts [v2]
Neethu Prasad
nprasad at openjdk.org
Tue Aug 6 18:11:05 UTC 2024
> **Notes**
> This PR adds the following
> 1. info logging on number of SATB flush attempts
> 2. 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.058s][info][gc,stats ] Concurrent Marking = 0.080 s (a = 5351 us) (n = 15) (lvls, us = 4746, 5000, 5156, 5684, 5988)
> [4.058s][info][gc,stats ] SATB Flush Rendezvous = 0.013 s (a = 860 us) (n = 15) (lvls, us = 764, 814, 836, 885, 961)
> [4.058s][info][gc,stats ] Pause Final Mark (G) = 0.058 s (a = 3839 us) (n = 15) (lvls, us = 3047, 3320, 3867, 4121, 4930)
> [4.058s][info][gc,stats ] Pause Final Mark (N) = 0.054 s (a = 3592 us) (n = 15) (lvls, us = 2812, 3047, 3574, 3887, 4597)
> [4.058s][info][gc,stats ] Finish Mark = 0.028 s (a = 1843 us) (n = 15) (lvls, us = 1602, 1641, 1816, 1934, 2045)
> [4.058s][info][gc,stats ] Update Region States = 0.006 s (a = 386 us) (n = 15) (lvls, us = 375, 375, 381, 389, 413)
> [4.058s][info][gc,stats ] Choose Collection Set = 0.018 s (a = 1186 us) (n = 15) (lvls, us = 609, 619, 1309, 1387, 2109)
> [4.058s][info][gc,stats ] Rebuild Free Set = 0.001 s (a = 43 us) (n = 15) (lvls, us = 40, 41, 42, 43, 53)
> [4.058s][info][gc,stats ] Concurrent Weak References = 0.007 s (a = 452 us) (n = 15) (lvls, us = 420, 438, 443, 455, 487)
>
>
> on app termination
>
>
> [5.299s][info][gc,stats] GC STATISTICS:
> [5.299s][info][gc,stats] "(G)" (gross) pauses include VM time: time to notify and block threads, do the pre-
> [5.299s][info][gc,stats] and post-safepoint housekee...
Neethu Prasad has updated the pull request incrementally with one additional commit since the last revision:
ShenandoahTimingsTracker to support aggregation of cycle times
-------------
Changes:
- all: https://git.openjdk.org/jdk/pull/20318/files
- new: https://git.openjdk.org/jdk/pull/20318/files/7c3d4a84..6e7fdd5e
Webrevs:
- full: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=01
- incr: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=00-01
Stats: 31 lines in 5 files changed: 9 ins; 6 del; 16 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