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 hotspot-gc-dev mailing list