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

[Aleksey Shipilev]

On Thu, 25 Jul 2024 16:14:39 GMT, Aleksey Shipilev <shade at openjdk.org> wrote:

>> **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 p...
>
> src/hotspot/share/gc/shenandoah/shenandoahConcurrentMark.cpp line 234:
> 
>> 232:   timings->record_phase_time(ShenandoahPhaseTimings::conc_mark_satb_flush_rendezvous, handshake_total_time);
>> 233: 
>> 234:   log_info(gc, phases) ("Total SATB flush attempts : %d", (flushes + 1));
> 
> Instead of this, I suggest we wrap the `Handshake::execute` with `log_info(gc,phases,start)` and `log_info(gc,phases)`. Logging would tell us how many attempts were done, and give us a rough number how long it took. The benefit would be that we would have the exact timestamps when handshakes started/finished.

Hm. Maybe even better to wrap it with:


    {
      ShenandoahTimingsTracker t(ShenandoahPhaseTimings::conc_mark_satb_flush_rendezvous, true);
      Handshake::execute(&flush_satb);
    }


Note the last, new argument that allows to merge multiple events into one. We need to separately make `ShenandoahTimingsTracker` report `gc,phases` log statement, imo.

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

PR Review Comment: https://git.openjdk.org/jdk/pull/20318#discussion_r1691943083