JEP 271: Unified GC Logging

[Staffan Friberg]

On 09/25/2015 02:39 AM, Bengt Rutisson wrote:
>
>
> On 2015-09-24 19:02, Kirk Pepperdine wrote:
>> Hi Bengt,
>>
>>>
>>>>
>>>>
>>>> For example, if you are not interested in the timing of the 
>>>> different phases, but still want to know the eden/survivor usage 
>>>> you can run with -Xlog:gc,gc+heap=debug and you get this 
>>>> information for each GC:
>>>>
>>>> [0,771s][info   ][gc     ] GC#14 start [young, G1 Evacuation Pause]
>>>> [0,788s][debug  ][gc,heap] GC#14 Eden:     Used before: 15,0M Used 
>>>> after:    0,0B Capacity:   14,0M
>>>> [0,788s][debug  ][gc,heap] GC#14 Survivor: Used before: 3072,0K 
>>>> Used after: 3072,0K Capacity: 3072,0K
>>>> [0,788s][debug  ][gc,heap] GC#14 Heap:     Used before: 111,2M Used 
>>>> after:   97,1M Capacity:  128,0M
>>>> [0,788s][info   ][gc     ] GC#14 end [111,2M->97,1M(128,0M)] 
>>>> [16,651 ms]
>> I should have added that I never saw the point to the more verbose 
>> lines Eden: Used before and so on when the summary 111.2M->97M 
>> conveyed the exact same information. I’ve not found anyone in my 
>> performance tuning workshop that is put off with that format either. 
>> In fact, every generally goes straight to using tooling and I have to 
>> cattle prod them to look at the log. If you think you need the 
>> information for debugging so be it.
>
> Am I interpreting you correctly that you think the three lines for 
> eden/survivor/heap are too verbose. That the "111,2M->97,1M(128,0M)" 
> logging is enough? That's a valid comment I just wanted to make sure I 
> understand you correctly.
>
> I've had to explain that output so many times to different people that 
> I thought it would be better to be a bit more verbose and hopefully 
> ease the understanding of the log output a bit. But I'm open to 
> changing it.

I believe it is worthwhile keeping the three output lines as this allows 
how much was copied to surv vs. old space. Which I believe wouldn't be 
possible to see if only looking at "end" line. Perhaps "summary" would 
be a clearer header for the "end" line?

 > [Times: user=0,10 sys=0,00 real=0,02 secs]
Skip the angle brackets here?

I like the GC ID being printed on each line! Will make life much easier.

Thanks,
Staffan