JEP 271: Unified GC Logging - Second pre-review

Kirk Pepperdine kirk.pepperdine at
Sat Nov 7 11:24:33 UTC 2015

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


> On Nov 6, 2015, at 5:08 PM, Bengt Rutisson <bengt.rutisson at> 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:
> The webrev for the changes is available here:
> 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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <>

More information about the hotspot-gc-dev mailing list