JEP 271: Unified GC Logging - Second pre-review

Bengt Rutisson bengt.rutisson at oracle.com
Mon Nov 9 09:12:32 UTC 2015


Hi Kirk,

On 2015-11-08 00:28, Kirk Pepperdine wrote:
> Hi Bernd,
>
> I’m with you that the format stabilization is a great improvement. As far a parsability is concerned, don’t really care were the time stamp sits as long as it’s stable. So having the GCId up front is ok. From my POV, GCID isn’t really all that useful so I’ll most likely ignore it anyways. In general what I’m suggesting can be dropped is stuff I’ll end up ignoring anyways. The way I see it, no point in generating it, stuff it down to disk and storing it if all you’re going to do is ignore it.. but this is what it is so….
>
> What I’d like to see if the date stamp

The unified logging framework can give you date stamps as decorations:

[2015-11-09T10:10:47.516+0100] GC#35 GC young (G1 Evacuation Pause) 
110M->70M(128M) (1.531s, 1.542s) 11.615ms

Regards,
Bengt

>
> Regards,
> Kirk
>
>> On Nov 7, 2015, at 4:58 PM, ecki at zusammenkunft.net wrote:
>>
>> Hello,
>>
>> Besides the question with the "start" tagged redundancy and the multiline events (which as Kirk brought up can be collapsed), I do like the new layout but I find the timestamps a bit hard to understand by looking at it (yes one can get used to it, but there is room to make it a bit more intuitive). Would it be an option to print the "real start time" at the front (before or after the gc id) so it is clear it is the relative start time of the event? (This is especially usefull if the logger decorates with absolute timestamps, so you have the relative ones in a fixed column next to it. It also helps the parser to extract those fixed parts)
>>
>> [11.247s][info   ][gc          ] GC#265 (11.228s - 11.247s) GC young (G1 Evacuation Pause) 109M->71M(128M)  19.208ms
>>
>> Sorry for bringing this up late, but it seems to declutter the gc event specific numbers. (Leaving the duration at the end in this case)
>>
>> BTW the whole GC tooling community will love you, Bengt! ;)
>>
>> Gruss
>> Bernd
>> --
>> http://bernd.eckenfels.net
>>
>> -----Original Message-----
>> From: Kirk Pepperdine <kirk.pepperdine at gmail.com>
>> To: Bengt Rutisson <bengt.rutisson at oracle.com>
>> Cc: "hotspot-gc-dev at openjdk.java.net openjdk.java.net" <hotspot-gc-dev at openjdk.java.net>
>> Sent: Sa., 07 Nov. 2015 13:25
>> Subject: Re: JEP 271: Unified GC Logging - Second pre-review
>>
>> Hi Bengt,
>>
>> A couple of comments aimed at bulk and/or frequency trade-offs.
>>
>> [11.247s][info   ][gc          ] GC#265 GC young (G1 Evacuation Pause) 109M->71M(128M) (11.228s, 11.247s) 19.208ms
>> with the exception of the pause time, this line seems redundant.
>>
>> [11.247s][info   ][gc,heap     ] GC#265 Eden: 38912K->0K(2048K)
>> [11.247s][info   ][gc,heap     ] GC#265 Survivor: 4096K->4096K(6144K)
>> [11.247s][info   ][gc,heap     ] GC#265 Old: 68990K->73147K(131072K)
>> [11.247s][info   ][gc,metaspace] GC#265 Metaspace: 2993K->2993K(1056768K)
>> can these 4 lines be combined?
>>
>> [11.726s][info   ][gc,start    ] GC#269 GC remark (11.726s)
>> [11.740s][info   ][gc          ] GC#269 GC remark 76M->76M(128M) (11.726s, 11.740s) 14.211ms
>> the paired timing seems redundant (as it does for all the other phases).
>>
>>  From the other examples follows the same theme that there is frequent logging of very small records that look like they should be combined. From this example, could the reference processing be collapsed into a single entry?
>> [1.118s][trace  ][gc,start    ] GC#2 DefNew (Allocation Failure) (1.118s)
>> [1.189s][debug  ][gc,ref,start] GC#2 SoftReference (1.189s)
>> [1.189s][debug  ][gc,ref      ] GC#2 SoftReference (1.189s, 1.189s) 0.038ms
>> [1.189s][debug  ][gc,ref,start] GC#2 WeakReference (1.189s)
>> [1.189s][debug  ][gc,ref      ] GC#2 WeakReference (1.189s, 1.189s) 0.009ms
>> [1.189s][debug  ][gc,ref,start] GC#2 FinalReference (1.189s)
>> [1.189s][debug  ][gc,ref      ] GC#2 FinalReference (1.189s, 1.189s) 0.007ms
>> [1.189s][debug  ][gc,ref,start] GC#2 PhantomReference (1.189s)
>> [1.189s][debug  ][gc,ref      ] GC#2 PhantomReference (1.189s, 1.189s) 0.007ms
>> [1.189s][debug  ][gc,ref,start] GC#2 JNI Weak Reference (1.189s)
>> [1.189s][debug  ][gc,ref      ] GC#2 JNI Weak Reference (1.189s, 1.189s) 0.008ms
>> [1.189s][debug  ][gc,ref      ] GC#2 Ref Counts: Soft 0 Weak: 0 Final: 0 Phantom: 0
>> [1.195s][debug  ][gc,age      ] GC#2 Desired survivor size 2228224 bytes, new threshold 15 (max threshold 15)
>> [1.195s][trace  ][gc,age      ] GC#2 - age   1:    1936136 bytes,    1936136 total
>> [1.195s][trace  ][gc          ] GC#2 DefNew (Allocation Failure) (1.118s, 1.195s) 76.775ms
>> [1.195s][debug  ][gc          ] GC#2 Collect gen: DefNew (1.118s, 1.195s) 76.822ms
>> [1.195s][info   ][gc,heap     ] GC#2 DefNew: 39296K->1890K(39296K)
>> [1.195s][info   ][gc,heap     ] GC#2 Tenured: 54815K->58866K(87424K)
>> [1.195s][info   ][gc,metaspace] GC#2 Metaspace: 2987K->2987K(1056768K)
>> [1.195s][info   ][gc          ] GC#2 GC pause, DefNew (Allocation Failure) 91M->59M(123M) (1.118s, 1.195s) 77.046ms
>> [1.195s][info   ][gc,cpu      ] GC#2 User=0.08s Sys=0.00s Real=0.08s
>>
>> Regards,
>> Kirk
>>
>>
>>
>>> On Nov 6, 2015, at 5:08 PM, Bengt Rutisson <bengt.rutisson at oracle.com> wrote:
>>>
>>>
>>> Hi everyone,
>>>
>>> Here is an updated pre-review for the work for JEP 271 Unified GC Logging.
>>>
>>> I've converted most of the GC logging now. Some of the CMS logging is still left to convert. In particular I've converted the PrintAdaptiveSizePolicy loggging. I turned that into logging on the "ergo" tag in combination with some other tags to give more fine grain control over the logging.
>>>
>>> Here are examples from the latest prototype:
>>> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/compare.html
>>>
>>> The webrev for the changes is available here:
>>> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/webrev.01/
>>>
>>> i haven't had a chance to address all comments from the last pre-review. CMS is still not completed, so the comments regarding the concurrent cycle logging have not been addressed. This is the next thing on my todo-list.
>>>
>>> Some of the thing that have changed since last time:
>>>
>>> - Added a timestamp in the "start" line for GC timing
>>> - Removed "start" and "end" words from the GC timing
>>> - Dropped "CPU Time" from the CPU time line
>>> - Converted most of the logging in the GC code base
>>>
>>> Thanks,
>>> Bengt
>>>



More information about the hotspot-gc-dev mailing list