<html>
<head>
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<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>
<tt><font size="-1"></font></tt><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>
</body>
</html>