RFR: 8336742: Shenandoah: Add more verbose logging/stats for mark termination attempts
Neethu Prasad
nprasad at openjdk.org
Thu Jul 25 21:06:31 UTC 2024
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
More information about the hotspot-gc-dev
mailing list