JEP 271: Unified GC Logging - First pre-review

[Bengt Rutisson]

On 2015-10-28 03:46, Yu Zhang wrote:
> Actually scratch that. I was confused with other pause time.

:)

Yes, these are "counts", so integers. Not doubles.

Bengt

> 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/20151028/03edea0e/attachment.htm>