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

[Neethu Prasad]

On Thu, 25 Jul 2024 18:18:46 GMT, Aleksey Shipilev <shade at openjdk.org> wrote:

>> 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.

Do we want something like below for conc_mark_satb_flush_rendezvous phase?
The log line is not useful for all the other usage of ShenandoahTimingTracker. So I'm thinking of logging only when boolean should_aggregate is set.

There will be two log lines when number of flush attempts = 2.


[3.475s][info][gc,phases   ] GC(14) Recorded time for phase SATB Flush Rendezvous as 0.615854 ms
[3.476s][info][gc,phases   ] GC(14) Recorded time for phase SATB Flush Rendezvous as 0.357069 ms

We can also have separate log line for start and end.

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

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