<html>
<head>
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<br>
<br>
<div class="moz-cite-prefix">On 2015-10-28 03:46, Yu Zhang wrote:<br>
</div>
<blockquote cite="mid:56303717.8040606@oracle.com" type="cite">
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
<font size="-1"><tt>Actually scratch that. I was confused with
other pause time.</tt></font><br>
</blockquote>
<br>
:)<br>
<br>
Yes, these are "counts", so integers. Not doubles.<br>
<br>
Bengt<br>
<br>
<blockquote cite="mid:56303717.8040606@oracle.com" type="cite">
<pre class="moz-signature" cols="72">Thanks,
Jenny</pre>
<div class="moz-cite-prefix">On 10/27/2015 7:30 PM, Yu Zhang
wrote:<br>
</div>
<blockquote cite="mid:56303354.20702@oracle.com" type="cite">
<meta content="text/html; charset=utf-8"
http-equiv="Content-Type">
<font size="-1"><tt>Bengt,<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/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 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>
</blockquote>
<br>
</blockquote>
<br>
</body>
</html>