RFR: 8336742: Shenandoah: Add more verbose logging/stats for mark termination attempts [v6]

Neethu Prasad nprasad at openjdk.org
Tue Aug 13 16:50:25 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:

  Fix indentation and naming

-------------

Changes:
  - all: https://git.openjdk.org/jdk/pull/20318/files
  - new: https://git.openjdk.org/jdk/pull/20318/files/1609ed50..da599599

Webrevs:
 - full: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=05
 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=20318&range=04-05

  Stats: 3 lines in 3 files changed: 0 ins; 0 del; 3 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