RFR: 8344263: GenShen: Reduce extraneous log messages at INFO level [v2]

[William Kemper]

On Fri, 15 Nov 2024 11:26:58 GMT, Aleksey Shipilev <shade at openjdk.org> wrote:

>> William Kemper has updated the pull request incrementally with one additional commit since the last revision:
>> 
>>   Log heuristics decisions at info with ergo tag
>
> Sorry, maybe I was too hard about `debug`. Maybe it should be `gc,ergo=info` instead, like the rest of heuristics code. "Want to see GC did? Enable -Xlog:gc. Want to see _why_ GC did it? Enable -Xlog:gc+ergo."

@shipilev - meet in the middle? Log heuristic's decisions at `info` with tag `ergo`, the rest of the changes in this PR continue logging at `debug`.

@ysramakrishna - A typical young cycle looks like this:


[3.055s][info][gc] Trigger (YOUNG): Average GC time (22.07 ms) is above the time for average allocation rate (53621 KB/s) to deplete free headroom (0B) (margin of error = 1.91)
[3.055s][info][gc] GC(29) Concurrent reset (Young) 0.042ms
[3.055s][info][gc] GC(29) Pause Init Mark (Young) 0.037ms
[3.055s][info][gc] GC(29) Concurrent remembered set scanning 0.064ms
[3.056s][info][gc] GC(29) Concurrent marking roots 0.278ms
[3.057s][info][gc] GC(29) Concurrent marking (Young) 1.779ms
[3.058s][info][gc] GC(29) Pause Final Mark (Young) 0.116ms
[3.058s][info][gc] GC(29) Concurrent weak references (Young) 0.017ms
[3.058s][info][gc] GC(29) Concurrent weak roots (Young) 0.116ms
[3.058s][info][gc] GC(29) Concurrent cleanup (Young) 30M->30M(32M) 0.003ms


A typical cycle for the non-generational mode looks like this:


[2.729s][info][gc] Trigger (GLOBAL): Average GC time (52.17 ms) is above the time for average allocation rate (20698 KB/s) to deplete free headroom (0B) (margin of error = 3.29)
[2.729s][info][gc] GC(42) Concurrent reset  (unload classes) 0.068ms
[2.730s][info][gc] GC(42) Pause Init Mark  (unload classes) 0.018ms
[2.730s][info][gc] GC(42) Concurrent marking roots 0.390ms
[2.735s][info][gc] GC(42) Concurrent marking  (unload classes) 4.471ms
[2.735s][info][gc] GC(42) Pause Final Mark  (unload classes) 0.111ms
[2.735s][info][gc] GC(42) Concurrent thread roots 0.080ms
[2.735s][info][gc] GC(42) Concurrent weak references  (unload classes) 0.047ms
[2.736s][info][gc] GC(42) Concurrent weak roots  (unload classes) 0.740ms
[2.736s][info][gc] GC(42) Concurrent cleanup  (unload classes) 4M->4M(32M) 0.002ms
[2.744s][info][gc] GC(42) Concurrent class unloading 8.163ms
[2.744s][info][gc] GC(42) Concurrent strong roots 0.158ms
[2.745s][info][gc] GC(42) Concurrent evacuation 0.420ms
[2.745s][info][gc] GC(42) Pause Init Update Refs 0.008ms
[2.747s][info][gc] GC(42) Concurrent update references 2.494ms
[2.747s][info][gc] GC(42) Concurrent update thread roots 0.310ms
[2.748s][info][gc] GC(42) Pause Final Update Refs 0.044ms
[2.748s][info][gc] GC(42) Concurrent cleanup  (unload classes) 13M->12M(32M) 0.029ms

The `Trigger` still shows the generational name in non-generational modes. I'll see about that.

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

PR Comment: https://git.openjdk.org/shenandoah/pull/540#issuecomment-2479781360