JEP 271: Unified GC Logging - First pre-review

Yu Zhang yu.zhang at oracle.com
Wed Oct 28 02:30:44 UTC 2015


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


More information about the hotspot-gc-dev mailing list