JEP 271: Unified GC Logging

[Poonam Bajaj Parhar]

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
>