JEP 271: Unified GC Logging - First pre-review

Tue Oct 27 13:48:56 UTC 2015

Hello Bengt,

On 10/27/2015 2:30 AM, Bengt Rutisson wrote:
>
> One comment inline.
>
> On 2015-10-27 07:22, Bengt Rutisson wrote:
>>
>> Hi Poonam,
>>
>> Thanks for looking at this!
>>
>>
>> On 2015-10-26 21:22, Poonam Bajaj Parhar wrote:
>>> Hello Bengt,
>>>
>>> I am going to try out the new logging myself but some quick feedback 
>>> from the examples output you had provided:
>>>
>>> *-Xlog:gc:*
>>>
>>> 1. It is great to have the start and end timestamps included on the 
>>> same GC log line.
>>
>> Great! :)
>>
>>>
>>> 2.
>>> /[0.643s][info   ][gc] GC#5 GC young (G1 Evacuation Pause) end 91M->61M(128M) (0.632s, 0.643s) 11.399ms//
>>> //[1.499s][info   ][gc] GC#16 GC remark end 73M->73M(128M) (1.486s, 1.499s) 12.545ms
>>> [1.500s][info   ][gc] GC#16 GC cleanup end 73M->73M(128M) (1.499s, 1.500s) 0.729ms/
>>>
>>> It does not make much of a sense here to include 'end' in the log 
>>> lines. If there is no line with a 'start' then I think it does not 
>>> serve any purpose to have 'end' for these GC lines.
>>
>> I see your point. However, when the start logging is included I think 
>> it makes sense to have some marker on this line saying that it is the 
>> end logging. I would prefer that the line looks exactly the same in 
>> both cases. But I am very open to suggestions for another way to 
>> format the line. I agree that it looks odd with "end" when there is 
>> no start. On the other hand the logging is done at the end of the GC, 
>> which could be relevant to include in the information. I've been 
>> thinking about "done" instead. Or "completed". Any other suggestions?
>>
>>>
>>> 3. There are some white-spaces after the 'level' ([info   ]), it'd 
>>> be good if those can be removed.
>>
>> This is from the logging framework and not part of the GC log 
>> implementation. I think you need to bring this up on the 
>> serviceability list.
>>
>>
>>>
>>> *-Xlog:gc***:*
>>>
>>> 1. Is there a specific reason to print the tag (gc) and other 
>>> sub-tags in different order? For example, we have 'start, gc', and 
>>> the order is different in 'gc, heap'.
>>> /
>>> [1.300s][info   ][start,gc    ] GC#3 GC (Allocation Failure) DefNew start
>>> [1.300s][info   ][start,gc    ] GC#4 Full GC (Allocation Failure) start
>>> [2.154s][info   ][gc          ] GC#4 Full GC (Allocation Failure) end 93M->59M(123M) (1.300s, 2.154s) 854.130ms
>>> [2.154s][info   ][gc,heap     ] GC#3 def new generation: 36767K->0K(39296K)
>>> [2.154s][info   ][gc,heap     ] GC#3 tenured generation: 58893K->61204K(87424K)
>>> [2.154s][info   ][gc,metaspace] GC#3 Metaspace: 2953K->2953K(1056768K)
>>> /if possible, I think we should have the order 'main-tag, sub-tag' 
>>> at all the places.
>>
>> Very well spotted! There is a technical reason for this. I have been 
>> trying to work around it but for now the simplest solution was to 
>> have the start tag first.
>>
>> The technical reason is that the "start" tag is added to any other 
>> tags for the timing class that is used to track the time for a GC (or 
>> a GC sub event). Currently the only way to add an extra tag is to do 
>> it at the beginning of the tag set.
>>
>> I can try to work around this, or try to get the unified logging 
>> framework to let me append a tag instead. But if it is ok I'd like to 
>> leave it like this for now and file an RFE to fix this later.
>
> I've found a workaround for this issue. Now the start tag is added at 
> the end of the list:
>
> [1.504s][info   ][gc,start    ] GC#3 GC (Allocation Failure) DefNew 
> (1.504s)
> [1.504s][info   ][gc,start    ] GC#4 Full GC (Allocation Failure) (1.504s)
> [2.368s][info   ][gc          ] GC#4 Full GC (Allocation Failure) end 
> 93M->59M(123M) (1.504s, 2.368s) 864.403ms
> [2.368s][info   ][gc,heap     ] GC#3 def new generation: 
> 36839K->0K(39296K)
> [2.368s][info   ][gc,heap     ] GC#3 tenured generation: 
> 58872K->61221K(87424K)
> [2.368s][info   ][gc,metaspace] GC#3 Metaspace: 2953K->2953K(1056768K)
> [2.368s][info   ][gc          ] GC#3 GC (Allocation Failure) DefNew 
> end 93M->59M(123M) (1.504s, 2.368s) 864.653ms
> [2.368s][info   ][gc,cpu      ] GC#3 CPU Times: user=0.86s sys=0.00s 
> real=0.86s
>
>
> I've also included the start time stamp in the "start" logging line.

This looks good!

Thanks,
Poonam

>
> Thanks,
> Bengt
>
>>
>> Thanks,
>> Bengt
>>
>>>
>>> Thanks,
>>> Poonam
>>>
>>> On 10/26/2015 5:26 AM, Bengt Rutisson wrote:
>>>>
>>>> Hi again everyone,
>>>>
>>>> An update on the work for JEP 271 Unified GC Logging.
>>>>
>>>> I now have a working prototype that covers all GCs. Here are some 
>>>> examples comparing the old format (using -XX:+PrintGC and 
>>>> -XX:+PrintGCDetails) with the new format (using -Xlog):
>>>>
>>>> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/compare.html 
>>>>
>>>>
>>>> The new logging format, using -Xlog, is much more flexible than the 
>>>> old format. So, the comparison table on the above page is by no 
>>>> means complete. I hope it will give a good overview, but to get a 
>>>> real feel for how the new logging works I think it is necessary to 
>>>> run locally and play around with the logging options.
>>>>
>>>> Here is a webrev of the changes so far:
>>>> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/webrev.00/
>>>>
>>>> There is still work to do and I have some known issues with the 
>>>> code changes. So, I am currently not asking for too much feedback 
>>>> on the actual code changes. I am more looking for feedback on the 
>>>> logging behavior. The webrev can be useful to get a feel for what 
>>>> the code changes will look like but mostly I think it can be used 
>>>> to apply the patch and build your own HotSpot to try out the new 
>>>> logging.
>>>>
>>>> Some changes based on the initial feedback:
>>>> - Start and end timestamps for the GC included on the GC log line.
>>>> - Printing the unit of a value without a space. I.e. "10.345ms" 
>>>> instead of "10.345 ms". (Still working on fixing this in all places 
>>>> as well as trying to use milliseconds instead of seconds in as many 
>>>> places as possible.)
>>>> - Printing heap change information with a fixed unit. I am now 
>>>> using M for overall heap transition and K for detailed information 
>>>> on the debug level.
>>>> - Removed the "summary" tag. Instead the end logging for a GC 
>>>> includes all relevant information.
>>>>
>>>> All feedback is very welcome!
>>>>
>>>> Thanks,
>>>> Bengt
>>>
>>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20151027/3c513c3d/attachment.htm>