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

[Aleksey Shipilev]

On Tue, 6 Aug 2024 18:11:05 GMT, Neethu Prasad <nprasad at openjdk.org> wrote:

>> **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...
>
> Neethu Prasad has updated the pull request incrementally with one additional commit since the last revision:
> 
>   ShenandoahTimingsTracker to support aggregation of cycle times

Looks okay, only stylistic comments:

src/hotspot/share/gc/shenandoah/shenandoahPhaseTimings.cpp line 142:

> 140: void ShenandoahPhaseTimings::set_cycle_data(Phase phase, double time, bool should_aggregate_cycles) {
> 141:   if (should_aggregate_cycles) {
> 142:     _cycle_data[phase] = _cycle_data[phase] <= 0 ? time :  _cycle_data[phase] + time;

I *think* `<= 0` is too broad, and assumes things about the value of `uninitialized()`. Check for `uninitialized()` explicitly.

src/hotspot/share/gc/shenandoah/shenandoahUtils.cpp line 127:

> 125:   const double end_time = os::elapsedTime();
> 126:   const double phase_elapsed_time = end_time - _start;
> 127:   _timings->record_phase_time(_phase, phase_elapsed_time, _should_aggregate_cycles);

No need to introduce local variables here, right? The expression can stay inlined.

src/hotspot/share/gc/shenandoah/shenandoahUtils.hpp line 69:

> 67:   ShenandoahPhaseTimings::Phase         _parent_phase;
> 68:   double _start;
> 69:   bool _should_aggregate_cycles;

How about simplifying it to `_should_aggregate`?

src/hotspot/share/gc/shenandoah/shenandoahUtils.hpp line 72:

> 70: 
> 71: public:
> 72:   ShenandoahTimingsTracker(ShenandoahPhaseTimings::Phase phase, bool should_aggregate_cycles=false);

Here and everywhere else, need whitespaces: `bool should_aggregate_cycles = false`

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

PR Review: https://git.openjdk.org/jdk/pull/20318#pullrequestreview-2221968957
PR Review Comment: https://git.openjdk.org/jdk/pull/20318#discussion_r1705945023
PR Review Comment: https://git.openjdk.org/jdk/pull/20318#discussion_r1705943889
PR Review Comment: https://git.openjdk.org/jdk/pull/20318#discussion_r1705943175
PR Review Comment: https://git.openjdk.org/jdk/pull/20318#discussion_r1705943455