JEP 271: Unified GC Logging - First pre-review

[Bengt Rutisson]

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.

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