RFE: -Xlog:gc to show pause/concurrent phases duration and heap occupancy

[Per Liden]

Hi Aleksey,

The logging code in ZGC is in the middle of a transitions from the "old" 
style to a "new" style. The transitions isn't complete yet, which is why 
it might not appear optimal at this time.

In the "old" style, we had pretty much what you propose, which is also 
sort of similar to what G1 and CMS is doing. However, we believe we have 
is a great opportunity to re-think and improve things, which is why we 
started this transition. Once completed, I think it will serve both 
users and GC devs better.

In the "new" style, we're aiming for the following:

* -Xlog:gc - Enables basic logging. Basically one single line per GC, 
non-verbose, giving you only the most important information. This is 
something you would typically enable when you just want to keep an eye 
on what the GC does, to get a feeling for the heap size, pause times, 
etc. It's not intended for anyone who wants to tune or dig deeper. 
Rather, something you might use once all tuning is completed, but you 
still want some information. A user that isn't very familiar with (or 
care) how ZGC works internally should still find this information 
useful. The line we print today is missing some time-related 
information. This line will in the future look something like this:

GC(0) Garbage Collection (Warmup) 1646M(10%)->596M(4%), 1.0ms/1.1ms/1.2ms

Where the last three numbers represent the pause times (mark start, mark 
end, reloc start) during that GC cycle. We might also want to add some 
notion of the total GC cycle time here.


* -Xlog:gc* - Enable verbose logging. This is the go to logging option 
when you want to tune, debug or dig deeper. Obviously much more verbose, 
making use of appropriate log tags so that the output can be 
refined/filtered as needed. Interpreting information here typically 
requires some level of understanding of ZGC. Many of the log tag 
combinations have additional information on the debug/trace level, 
normally only useful for GC devs debugging the ZGC itself. The output 
you see today in this mode is also in the middle of our transition, and 
hence incomplete. We plan to move much of the information currently 
printed in the gc+stats table in under more specific tags and let them 
be printed once per GC.


While there's some value in having different GCs do logging in a similar 
way, I see an even greater value in providing really good and useful 
logging. In both ZGC and Shenandoah we have the rare opportunity to make 
things better, without having to deal with old baggage or old ways of 
doing things, which we're trying to embrace.


cheers,
Per

On 2017-12-11 17:52, Aleksey Shipilev wrote:
> Current -Xlog:gc log with ZGC is rather opaque:
>
> [19.964s][info][gc] GC(0) Garbage Collection (Warmup) 1646M(10%)->596M(4%)
> [31.690s][info][gc] GC(1) Garbage Collection (Warmup) 3304M(20%)->384M(2%)
> [38.666s][info][gc] GC(2) Garbage Collection (Warmup) 5004M(31%)->1428M(9%)
> [46.724s][info][gc] GC(3) Garbage Collection (Allocation Rate) 9198M(56%)->8132M(50%)
> [49.010s][info][gc] GC(4) Garbage Collection (Allocation Rate) 8596M(52%)->9786M(60%)
> [51.373s][info][gc] GC(5) Garbage Collection (Allocation Rate) 10348M(63%)->9800M(60%)
> [53.698s][info][gc] GC(6) Garbage Collection (Allocation Rate) 10002M(61%)->10724M(65%)
> [55.434s][info][gc] GC(7) Garbage Collection (Allocation Rate) 10778M(66%)->7956M(49%)
> [57.446s][info][gc] GC(8) Garbage Collection (Allocation Rate) 8420M(51%)->10896M(67%)
>
> The real pause work hides under -Xlog:gc+phases:
>
> [197.362s][info][gc,phases] GC(108) Pause Mark Start 0.697ms
> [198.119s][info][gc,phases] GC(108) Concurrent Mark 757.226ms
> [198.135s][info][gc,phases] GC(108) Pause Mark End 0.802ms
> [198.136s][info][gc,phases] GC(108) Concurrent References Processing 1.461ms
> [198.149s][info][gc,phases] GC(108) Concurrent Reset Relocation Set 12.285ms
> [198.154s][info][gc,phases] GC(108) Concurrent Destroy Detached Pages 0.001ms
> [198.158s][info][gc,phases] GC(108) Concurrent Select Relocation Set 3.239ms
> [198.332s][info][gc,phases] GC(108) Concurrent Prepare Relocation Set 173.931ms
> [198.333s][info][gc,phases] GC(108) Pause Relocate Start 1.010ms
> [198.819s][info][gc,phases] GC(108) Concurrent Relocate 485.961ms
>
> Can/should we redo this to match what e.g. Shenandoah is doing: phases to be at "gc" tag, and
> concurrent phases to report how heap had changed while phases were running? This should help new
> users to understand what collector is doing better, and also allow better comparison against other
> OpenJDK collectors, that report heap occupancy and pauses under "gc" tag.
>
> So ZGC output would look like:
>
> [info][gc] GC(108) Pause Mark Start 0.697ms
> [info][gc] GC(108) Concurrent Mark xxxxM->xxxxM 757.226ms
> [info][gc] GC(108) Pause Mark End 0.802ms
> [info][gc] GC(108) Concurrent References Processing xxxxM->xxxxM 1.461ms
> [info][gc] GC(108) Concurrent Prepare Relocate xxxxM->xxxxM 12.285ms
> [info][gc] GC(108) Pause Relocate Start 1.010ms
> [info][gc] GC(108) Concurrent Relocate xxxxM->xxxxM 485.961ms
>
> "Prepare Relocate" combines all Relocation Set activities -- those can be under gc+phases if anyone
> wants it.
>
> Thanks,
> -Aleksey
>