JEP 271: Unified GC Logging - Second pre-review

[Bengt Rutisson]

Hi Kirk,

On 2015-11-08 00:33, Kirk Pepperdine wrote:
>> On Nov 7, 2015, at 5:10 PM, Simone Bordet <sbordet at webtide.com> wrote:
>>
>> Hi,
>>
>> On Sat, Nov 7, 2015 at 12:24 PM, Kirk Pepperdine
>> <kirk.pepperdine at gmail.com> wrote:
>>> Hi Bengt,
>>>
>>> A couple of comments aimed at bulk and/or frequency trade-offs.
>>>
>>> [11.247s][info   ][gc          ] GC#265 GC young (G1 Evacuation Pause)
>>> 109M->71M(128M) (11.228s, 11.247s) 19.208ms
>>>
>>> with the exception of the pause time, this line seems redundant.
>>>
>>> [11.247s][info   ][gc,heap     ] GC#265 Eden: 38912K->0K(2048K)
>>> [11.247s][info   ][gc,heap     ] GC#265 Survivor: 4096K->4096K(6144K)
>>> [11.247s][info   ][gc,heap     ] GC#265 Old: 68990K->73147K(131072K)
>>> [11.247s][info   ][gc,metaspace] GC#265 Metaspace: 2993K->2993K(1056768K)
>>>
>>> can these 4 lines be combined?
>> Don't we also need some number to calculate the promoted bytes ?
>> I was doing this before using: promoted = total_young_delta - total_heap_delta.
> Ok, let me suggest a format. This is all the information I need. Everything else is chatter.
>
>>> [11.247s][info   ][gc,heap     ] GC#265 38912K->0K(2048K) 4096K->4096K(6144K) 68990K->73147K(131072K) 2993K->2993K(1056768K)

This format may be fine for machine parsing but it is not very readable 
to humans. Readability is an important use case, so we will need to at 
least add information about what the numbers map to. As I stated in a 
previous mail I would prefer these on separate lines, but if we want 
them on a single line I think the format need to be something like:

[11.247s][info   ][gc,heap     ] GC#265 Eden: 38912K->0K(2048K), 
Survivor: 4096K->4096K(6144K), Old: 68990K->73147K(131072K), Metaspace: 
2993K->2993K(1056768K)

To me this is line is too long to ready quickly. In particular if I am 
just trying to follow how, for example, the Eden size changes over time.

Thanks,
Bengt

>
>
>> With the above proposal, how would one know if the old generation
>> delta is entirely due to promotion or if there was some cleanup (e.g.
>> mixed GCs) that affected the old generation ?
>>
>> For my use cases the 3 most important value I would like to easily
>> detect are the allocation rate, the promotion rate and the GC times.
> agreed but these are easily derived for full STW collectors, a bitch for concurrent collectors are resets don’t report amounts released and young collections are consuming as the concurrent collection proceeds. I just extrapolate based on best guess in these case and that seems to work well enough
>
>> Allocation rate is kind-of easy by looking at Eden, although this
>> would not account for humongous allocations. I would appreciate if it
>> was more precise, accounting for humongous allocations as well.
> Good point, Humongous is technically another region and it’s important to track with the G1.
>
>> Promotion rate, I am not sure how to get it from what above, also
>> considering that total heap is in M while detailed generation is in K
>> (would be nicer they are in the same unit) so there could be important
>> inaccuracies.
> I’ve asked for resolution in K. M is far to coarse IMO.
>
> Regards,
> Kirk
>