JEP 271: Unified GC Logging - First pre-review

Tue Oct 27 09:30:24 UTC 2015

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.

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/ed84775b/attachment.htm>