<html><head><meta http-equiv="Content-Type" content="text/html charset=us-ascii"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class="">Hi Bengt,<div class=""><br class=""></div><div class="">A couple of comments aimed at bulk and/or frequency trade-offs.<br class=""><div class=""><br class=""></div><div class=""><pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class="">[11.247s][info ][gc ] GC#265 GC young (G1 Evacuation Pause) 109M->71M(128M) (11.228s, 11.247s) 19.208ms</pre><div class="">with the exception of the pause time, this line seems redundant.</div><div class=""><br class=""></div><div class=""><pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class="">[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)</pre><pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class=""><span style="font-family: Helvetica; white-space: normal; widows: auto;" class="">can these 4 lines be combined?</span></pre><pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class=""><span style="font-family: Helvetica; white-space: normal; widows: auto;" class=""><br class=""></span></pre><pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class=""><pre style="word-wrap: break-word; white-space: pre-wrap;" class="">[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</pre><div class=""><font face="Helvetica" class="">the paired timing seems redundant (as it does for all the other phases).</font></div><div class=""><font face="Helvetica" class=""><br class=""></font></div><div class=""><font face="Helvetica" class="">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?</font></div><div class=""><pre style="word-wrap: break-word; white-space: pre-wrap;" class="">[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</pre><pre style="word-wrap: break-word; white-space: pre-wrap;" class=""><br class=""></pre><pre style="word-wrap: break-word; white-space: pre-wrap;" class=""><font face="Helvetica" class="">Regards,</font></pre><pre style="word-wrap: break-word; white-space: pre-wrap;" class=""><span style="font-family: Helvetica;" class="">Kirk</span></pre><div class=""><br class=""></div></div><div class=""><br class=""></div></pre><div class=""><br class=""></div></div><div><blockquote type="cite" class=""><div class="">On Nov 6, 2015, at 5:08 PM, Bengt Rutisson <<a href="mailto:bengt.rutisson@oracle.com" class="">bengt.rutisson@oracle.com</a>> wrote:</div><br class="Apple-interchange-newline"><div class=""><br class="">Hi everyone,<br class=""><br class="">Here is an updated pre-review for the work for JEP 271 Unified GC Logging.<br class=""><br class="">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.<br class=""><br class="">Here are examples from the latest prototype:<br class=""><a href="http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/compare.html" class="">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/compare.html</a><br class=""><br class="">The webrev for the changes is available here:<br class="">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/webrev.01/<br class=""><br class="">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.<br class=""><br class="">Some of the thing that have changed since last time:<br class=""><br class="">- Added a timestamp in the "start" line for GC timing<br class="">- Removed "start" and "end" words from the GC timing<br class="">- Dropped "CPU Time" from the CPU time line<br class="">- Converted most of the logging in the GC code base<br class=""><br class="">Thanks,<br class="">Bengt<br class=""><br class=""></div></blockquote></div><br class=""></div></div></body></html>