JEP 271: Unified GC Logging - First pre-review

[Bengt Rutisson]

Hi Jenny,

On 2015-10-27 06:52, Yu Zhang wrote:
> Bengt,
>
> Can you also provide an example with -XX:+PrintAdaptiveSize

I'm currently working on converting the rest of the GC logging including 
the PrintAdaptiveSize logging. I'll post an example as soon as I have 
that completed.

>
> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/logs/G1-Xlog-gc-star-info.txt
> [0.400s][info ][start,gc ] GC#1 GC young (G1 Evacuation Pause) start
> [0.550s][info ][gc ] GC#1 To-space exhausted
> It seems the other entries are [gc,xxx ], except for [start,gc], 
> should it follow the same patten?

See my response to Poonam about that.

> Also the 'to-space exhausted' is on a separate line. I understand it 
> is a result of evacuation. But it might make parser easier to put them 
> in single line.

I think it makes sense to have it on a separate line. The GC id shows 
which GC it  belongs to. in general most logging will be on separate 
lines, which will also give better indication of when things happen. I 
think parsers much learn to group GC events by their GC id.

> [0.608s][info   ][start,gc    ] GC#4 GC young (G1 Evacuation Pause) start
> [0.621s][info   ][gc,heap     ] GC#4 Eden: 28672K->0K(28672K)
> [0.621s][info   ][gc,heap     ] GC#4 Survivor: 2048K->3072K(4096K)
> [0.621s][info   ][gc,heap     ] GC#4 Old: 75120K->78080K(131072K)
> [0.621s][info   ][gc,metaspace] GC#4 Metaspace: 2953K->2953K(1056768K)
> [0.621s][info   ][gc          ] GC#4 GC young (G1 Evacuation Pause) end 103M->76M(128M) (0.608s, 0.621s) 12.894ms
> I think the first 3 heap entries are for heap usage before gc, and the last line has the heap usage after gc, but those 2 formats are different. Probably better to stick to one.

No, the 3 detailed heap entries are for the heap transition over the 
whole GC. Their the same format that we've always used. "used 
before"->"used after"("capacity").

The reason they are in K instead of M is that I figured it would good to 
keep the "end GC" log line as short as possible. Printing values in M 
there saves a lot of characters. But for the single line heap 
transitions we have more space available on the line and it makes sense 
to use higher precision. Thus the K unit there.

> Also wondering those 2 timestamps in the parenthesis in the last line is helpful. Most of the time 12.894ms is more helpful.

This was explicitly asked for by Kirk and Poonam also liked it. It 
provides a way to decouple the GC timing from the log framework.

Thanks,
Bengt

>
>
> Thanks,
> Jenny
> 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/26d63cc6/attachment.htm>