<html>
<head>
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<font size="-1"><tt>Bengt,<br>
<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/logs/G1-printgcdetails.txt">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/logs/G1-printgcdetails.txt</a></tt></font><br>
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
<br>
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]<br>
Processed Buffers has Min as 0, can it be changed to 0.0, same for
sum? So it is consistent and parsing is easier?<br>
<pre class="moz-signature" cols="72">Thanks,
Jenny</pre>
<div class="moz-cite-prefix">On 10/26/2015 11:31 PM, Bengt Rutisson
wrote:<br>
</div>
<blockquote cite="mid:562F1A35.6060006@oracle.com" type="cite">
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
<br>
Hi Jenny,<br>
<br>
<div class="moz-cite-prefix">On 2015-10-27 06:52, Yu Zhang wrote:<br>
</div>
<blockquote cite="mid:562F111F.5000707@oracle.com" type="cite">
<meta content="text/html; charset=utf-8"
http-equiv="Content-Type">
<font size="-1"><tt>Bengt,<br>
<br>
Can you also provide an example with -XX:+PrintAdaptiveSize
<br>
</tt></font></blockquote>
<br>
I'm currently working on converting the rest of the GC logging
including the PrintAdaptiveSize logging. I'll post an example as
soon as I have that completed. <br>
<br>
<blockquote cite="mid:562F111F.5000707@oracle.com" type="cite"><font
size="-1"><tt> <br>
<a moz-do-not-send="true" class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Ebrutisso/JEP-271/pre-review.00/logs/G1-Xlog-gc-star-info.txt">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/logs/G1-Xlog-gc-star-info.txt</a><br>
</tt></font><small>[0.400s][info ][start,gc ] GC#1 GC young
(G1 Evacuation Pause) start <br>
[0.550s][info ][gc ] GC#1 To-space exhausted<br>
<small><small><big><big><small>It seems the other entries are
[gc,xxx ], except for [start,gc], should it follow
the same patten?<br>
</small></big></big></small></small></small></blockquote>
<br>
See my response to Poonam about that.<br>
<br>
<blockquote cite="mid:562F111F.5000707@oracle.com" type="cite"><small><small><small><big><big><small>
Also the 'to-space exhausted' is on a separate line.
I understand it is a result of evacuation. But it
might make parser easier to put them in single line.<br>
</small></big></big></small></small></small></blockquote>
<br>
I think it makes sense to have it on a separate line. The GC id
shows which GC it belongs to. in general most logging will be on
separate lines, which will also give better indication of when
things happen. I think parsers much learn to group GC events by
their GC id.<br>
<br>
<blockquote cite="mid:562F111F.5000707@oracle.com" type="cite"><small><small><small><big><big><small>
</small></big></big></small></small></small>
<pre style="color: rgb(0, 0, 0); font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; widows: 1; word-spacing: 0px; -webkit-text-stroke-width: 0px; word-wrap: break-word; white-space: pre-wrap;"><small><small>[</small></small>0.608s][info ][start,gc ] GC#4 GC young (G1 Evacuation Pause) start
[0.621s][info ][gc,heap ] GC#4 Eden: 28672K->0K(28672K)
[0.621s][info ][gc,heap ] GC#4 Survivor: 2048K->3072K(4096K)
[0.621s][info ][gc,heap ] GC#4 Old: 75120K->78080K(131072K)
[0.621s][info ][gc,metaspace] GC#4 Metaspace: 2953K->2953K(1056768K)
[0.621s][info ][gc ] GC#4 GC young (G1 Evacuation Pause) end 103M->76M(128M) (0.608s, 0.621s) 12.894ms
I think the first 3 heap entries are for heap usage before gc, and the last line has the heap usage after gc, but those 2 formats are different. Probably better to stick to one.</pre>
</blockquote>
<br>
No, the 3 detailed heap entries are for the heap transition over
the whole GC. Their the same format that we've always used. "used
before"->"used after"("capacity").<br>
<br>
The reason they are in K instead of M is that I figured it would
good to keep the "end GC" log line as short as possible. Printing
values in M there saves a lot of characters. But for the single
line heap transitions we have more space available on the line and
it makes sense to use higher precision. Thus the K unit there.<br>
<br>
<blockquote cite="mid:562F111F.5000707@oracle.com" type="cite">
<pre style="color: rgb(0, 0, 0); font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; widows: 1; word-spacing: 0px; -webkit-text-stroke-width: 0px; word-wrap: break-word; white-space: pre-wrap;">Also wondering those 2 timestamps in the parenthesis in the last line is helpful. Most of the time 12.894ms is more helpful.</pre>
</blockquote>
<br>
This was explicitly asked for by Kirk and Poonam also liked it. It
provides a way to decouple the GC timing from the log framework.<br>
<br>
Thanks,<br>
Bengt<br>
<br>
<blockquote cite="mid:562F111F.5000707@oracle.com" type="cite">
<pre style="color: rgb(0, 0, 0); font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; widows: 1; word-spacing: 0px; -webkit-text-stroke-width: 0px; word-wrap: break-word; white-space: pre-wrap;">
</pre>
<pre class="moz-signature" cols="72">Thanks,
Jenny</pre>
<div class="moz-cite-prefix">On 10/26/2015 5:26 AM, Bengt
Rutisson wrote:<br>
</div>
<blockquote cite="mid:562E1BE5.7090604@oracle.com" type="cite">
<br>
Hi again everyone, <br>
<br>
An update on the work for JEP 271 Unified GC Logging. <br>
<br>
I now have a working prototype that covers all GCs. Here are
some examples comparing the old format (using -XX:+PrintGC and
-XX:+PrintGCDetails) with the new format (using -Xlog): <br>
<br>
<a moz-do-not-send="true" class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Ebrutisso/JEP-271/pre-review.00/compare.html">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/compare.html</a>
<br>
<br>
The new logging format, using -Xlog, is much more flexible
than the old format. So, the comparison table on the above
page is by no means complete. I hope it will give a good
overview, but to get a real feel for how the new logging works
I think it is necessary to run locally and play around with
the logging options. <br>
<br>
Here is a webrev of the changes so far: <br>
<a moz-do-not-send="true" class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Ebrutisso/JEP-271/pre-review.00/webrev.00/">http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/webrev.00/</a>
<br>
<br>
There is still work to do and I have some known issues with
the code changes. So, I am currently not asking for too much
feedback on the actual code changes. I am more looking for
feedback on the logging behavior. The webrev can be useful to
get a feel for what the code changes will look like but mostly
I think it can be used to apply the patch and build your own
HotSpot to try out the new logging. <br>
<br>
Some changes based on the initial feedback: <br>
- Start and end timestamps for the GC included on the GC log
line. <br>
- Printing the unit of a value without a space. I.e.
"10.345ms" instead of "10.345 ms". (Still working on fixing
this in all places as well as trying to use milliseconds
instead of seconds in as many places as possible.) <br>
- Printing heap change information with a fixed unit. I am now
using M for overall heap transition and K for detailed
information on the debug level. <br>
- Removed the "summary" tag. Instead the end logging for a GC
includes all relevant information. <br>
<br>
All feedback is very welcome! <br>
<br>
Thanks, <br>
Bengt <br>
</blockquote>
<br>
</blockquote>
<br>
</blockquote>
<br>
</body>
</html>