JEP 271: Unified GC Logging - First pre-review

[Yu Zhang]

Actually scratch that. I was confused with other pause time.

Thanks,
Jenny

On 10/27/2015 7:30 PM, Yu Zhang wrote:
> Bengt,
>
> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/logs/G1-printgcdetails.txt
>  [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
>     [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
> Processed Buffers has Min as 0, can it be changed to 0.0, same for 
> sum? So it is consistent and parsing is easier?
> Thanks,
> Jenny
> On 10/26/2015 11:31 PM, Bengt Rutisson wrote:
>>
>> 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/a116e31c/attachment.htm>