Inclusion of pause time in gc.log

[Per Liden]

Hi,

On 09/25/2018 02:41 PM, Viton, Pedro (Nokia - ES/Madrid) wrote:
> Hi:
> 
> I've downloaded the latest Java11 Early Access to try out ZGC.
> I have to admit I'm really impressed with its reduced pause time, that I measure with MXBeans
> 
> I also like that the log line (included in gc.log, with default logging enabled) indicates the % of the heap before and after the collection
> [26.814s][info][gc] GC(0) Garbage Collection (Metadata GC Threshold) 168M(1%)->78M(1%)
> [28.719s][info][gc] GC(1) Garbage Collection (Metadata GC Threshold) 212M(2%)->94M(1%)
> [37.136s][info][gc] GC(2) Garbage Collection (Warmup) 3764M(31%)->1606M(13%)
> [45.807s][info][gc] GC(3) Garbage Collection (Allocation Rate) 6468M(53%)->2530M(21%)
> [48.553s][info][gc] GC(4) Garbage Collection (System.gc()) 2530M(21%)->1640M(13%)
> [114.713s][info][gc] GC(5) Garbage Collection (Allocation Rate) 6454M(53%)->2198M(18%)
> [165.234s][info][gc] GC(6) Garbage Collection (Allocation Rate) 8496M(69%)->3190M(26%)
> 
> I just have 1 suggestion:
> Would it be possible to also include in that log line, the pause time of the collection (as the addition of the 3 pauses for each collection)?

We've discussed various ways of showing this, for example like this

"Garbage Collection (Allocation Rate) 8496M(69%)->3190M(26%), 
1.302ms/0.987ms/1.211ms"

where those times would correspond the MarkStart/MarkEnd/RelocateStart 
pause times. It's a bit more to it though, since there are potentially 
more than one MarkEnd pause it's not obvious what to show there. The 
longest of the MarkEnd pauses is probably what most people want to see.

cheers,
Per

> 
> Thanks,
>                  Pedro
> 
> PEDRO VITON
> NOKIA
> AAA Specialist
> C/ Maria Tubau 9 (28050 Madrid - SPAIN)
> M: +34 690 964740 (ext. 2411 5746)
> pedro.viton at nokia.com<mailto:pedro.viton at alcatel-lucent.com>
>