JEP 271: Unified GC Logging

[Bengt Rutisson]

Hi Kirk, Poonam, Staffan, Bernd, Tao and Johann,

Thanks for all the great feedback on this and sorry for not being able 
to reply faster to your comments. I'm busy trying to make progress on 
the implementation. As soon as I have a more stable version of my 
prototype I'll post a webrev and some more examples.

I'll try to work your comments in to the implementation.

Thanks again for taking the time to look at this. I really appreciate it!

Bengt

On 2015-09-29 22:53, Poonam Bajaj Parhar wrote:
> Hello,
>
> On 9/29/2015 1:21 AM, Kirk Pepperdine wrote:
>>> On Sep 28, 2015, at 5:22 PM, Staffan Friberg <sfriberg at cloudera.com> 
>>> wrote:
>>>
>>>
>>> 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]
>> Hi Bengt,
>>
>> Some comments. Can you simply combine the information in the 4 lines 
>> into one line as follows.
>>
>>>>>>> [0,788s][info   ][gc     ] GC#14 [18432K->3072K(17408K)] 
>>>>>>> [114893K->99430K(131072K)] [16,651 ms]
>
> I really like the idea of logging all the required information at the 
> info level without being too verbose.
>
>> Collections of Eden should leave it empty hence the 3072K residual 
>> must be in survivor.  IMO, I'd say that this is the minimal amount of 
>> information that I’d like to see in a GC log. With total heap you can 
>> calculate all of the remaining residuals. Since this line should be 
>> the last line in the information printed for this collection you 
>> don’t really need the end tag. Same comment about the start tag. 
>> Numbers in K don’t need decimal points/commas so that eases the 
>> internationalization issue. If you want the breakdown in debug mode 
>> I’d say why not. However I’d be concerned about what other logging 
>> gets carried when you turn on debug mode (the ugly side effect of 
>> levels).
>
> At the debug level too, it'd we nice to follow the 
> before->after(capacity) format. e.g.
>
> [0,771s][info   ][gc     ] GC#14 start [young, G1 Evacuation Pause]
> [0,788s][debug  ][gc,heap] GC#14 Eden: [15000K->0K(14000K)]
> [0,788s][debug  ][gc,heap] GC#14 Survivor: [3072K->3072K(3072K)]
> [0,788s][debug  ][gc,heap] GC#14 Heap: [111200K->97100K(128000K)]
> [0,788s][info   ][gc     ] GC#14 end [111200K->97100K(128000K)] 
> [16.651 ms]
>
> Removing the text such as 'Used before' or 'Used after' that does not 
> have informational value would help in keeping the GC logging overhead 
> low. Also, having the size unit as K rather than M would be useful.
>
> Thanks,
> Poonam
>
>> Regards,
>> Kirk
>>
>