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

[Aleksey Shipilev]

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