JEP 271: Unified GC Logging - First pre-review

[Poonam Bajaj Parhar]

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.

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.

3. There are some white-spaces after the 'level' ([info   ]), it'd be 
good if those can be removed.

*-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.

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