<html>
<head>
<meta content="text/html; charset=windows-1252"
http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<br>
Hi Kirk,<br>
<br>
<div class="moz-cite-prefix">On 2015-11-07 12:24, Kirk Pepperdine
wrote:<br>
</div>
<blockquote
cite="mid:891D6DC0-A296-4B5C-B9DF-798F5C5915F1@gmail.com"
type="cite">
<meta http-equiv="Content-Type" content="text/html;
charset=windows-1252">
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>
</div>
</blockquote>
<br>
I may be misunderstanding your comment here, but this is the single
line that is printed for a GC if you just run with the "gc" tag at
info level, which I think will be the most common use case. I think
we want to know what type of GC it is (young), what the GC cause was
(G1 Evacuation Pause), what the heap change was and what the
duration was. You also wanted the start and stop timestamps. So, I
don't see the redundancy in this line.<br>
<br>
Maybe you mean that the information is redundant in the context of
other logging? Can you in that case provide some more context?<br>
<br>
<blockquote
cite="mid:891D6DC0-A296-4B5C-B9DF-798F5C5915F1@gmail.com"
type="cite">
<div class="">
<div 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,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>
</div>
</div>
</div>
</blockquote>
<br>
Technically they could be combined. I realize it would save some
space due to the decorations, but other than that I think it is
mostly a matter of taste if they should be on one line or separate
lines. Personally I find it easier to read them on separate lines.
Especially if I just want to follow one of them closely.<br>
<br>
<blockquote
cite="mid:891D6DC0-A296-4B5C-B9DF-798F5C5915F1@gmail.com"
type="cite">
<div class="">
<div class="">
<div class="">
<pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class=""><span style="font-family: Helvetica; white-space: normal; widows: auto;" 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 class="" face="Helvetica">the paired timing seems redundant (as it does for all the other phases).</font></div></pre>
</div>
</div>
</div>
</blockquote>
<br>
Since you can opt out of the "start" logging I think it is nice to
have the start timestamp in the "end" logging. I guess we can remove
the start timestamp from the "start" line, but I would prefer to
have it there. It kind of makes sense to have it there to make it
easier to detect discrepancies between the "GC" timestamp and the
timestamp provided by the logging framwork in the decoration.<br>
<br>
<blockquote
cite="mid:891D6DC0-A296-4B5C-B9DF-798F5C5915F1@gmail.com"
type="cite">
<div class="">
<div class="">
<div class="">
<pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class=""><div class=""><font class="" face="Helvetica">
</font></div><div class=""><font class="" face="Helvetica">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></div></pre>
</div>
</div>
</div>
</blockquote>
<br>
Again, maybe I am missunderstanding. But the idea with the "start"
tag is that you can easily turn it off. If you don't want the start
line just disable that part of the logging. For example by doing
"-Xlog:start*=off". That way you get a single entry for each timing
phase.<br>
<br>
Thanks for your feedback!<br>
Bengt<br>
<br>
<blockquote
cite="mid:891D6DC0-A296-4B5C-B9DF-798F5C5915F1@gmail.com"
type="cite">
<div class="">
<div class="">
<div class="">
<pre style="widows: 1; word-wrap: break-word; white-space: pre-wrap;" class=""><div class=""><pre style="word-wrap: break-word; white-space: pre-wrap;" class="">
</pre><pre style="word-wrap: break-word; white-space: pre-wrap;" class=""><font class="" face="Helvetica">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="">
</div></div><div 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 moz-do-not-send="true"
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 moz-do-not-send="true"
href="http://cr.openjdk.java.net/%7Ebrutisso/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="">
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/webrev.01/">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/webrev.01/</a><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>
</blockquote>
<br>
</body>
</html>