JEP 271: Unified GC Logging - Second pre-review

ecki at zusammenkunft.net ecki at zusammenkunft.net
Sat Nov 7 15:58:23 UTC 2015


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