<html>
<head>
<meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hello Bengt,<br>
<br>
<div class="moz-cite-prefix">On 10/27/2015 2:30 AM, Bengt Rutisson
wrote:<br>
</div>
<blockquote cite="mid:562F4430.3010301@oracle.com" type="cite">
<meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
<br>
One comment inline.<br>
<br>
<div class="moz-cite-prefix">On 2015-10-27 07:22, Bengt Rutisson
wrote:<br>
</div>
<blockquote cite="mid:562F1837.6000203@oracle.com" type="cite">
<meta content="text/html; charset=UTF-8"
http-equiv="Content-Type">
<br>
Hi Poonam,<br>
<br>
Thanks for looking at this!<br>
<br>
<br>
<div class="moz-cite-prefix">On 2015-10-26 21:22, Poonam Bajaj
Parhar wrote:<br>
</div>
<blockquote cite="mid:562E8B8C.10305@oracle.com" type="cite">
<meta content="text/html; charset=UTF-8"
http-equiv="Content-Type">
Hello Bengt,<br>
<br>
I am going to try out the new logging myself but some quick
feedback from the examples output you had provided:<br>
<br>
<b>-Xlog:gc:</b><br>
<br>
1. It is great to have the start and end timestamps included
on the same GC log line.<br>
</blockquote>
<br>
Great! :)<br>
<br>
<blockquote cite="mid:562E8B8C.10305@oracle.com" type="cite"> <br>
2.<br>
<pre><i>[0.643s][info ][gc] GC#5 GC young (G1 Evacuation Pause) end 91M->61M(128M) (0.632s, 0.643s) 11.399ms</i><i>
</i><i>[1.499s][info ][gc] GC#16 GC remark end 73M->73M(128M) (1.486s, 1.499s) 12.545ms
[1.500s][info ][gc] GC#16 GC cleanup end 73M->73M(128M) (1.499s, 1.500s) 0.729ms</i>
</pre>
<br>
It does not make much of a sense here to include 'end' in the
log lines. If there is no line with a 'start' then I think it
does not serve any purpose to have 'end' for these GC lines.<br>
</blockquote>
<br>
I see your point. However, when the start logging is included I
think it makes sense to have some marker on this line saying
that it is the end logging. I would prefer that the line looks
exactly the same in both cases. But I am very open to
suggestions for another way to format the line. I agree that it
looks odd with "end" when there is no start. On the other hand
the logging is done at the end of the GC, which could be
relevant to include in the information. I've been thinking about
"done" instead. Or "completed". Any other suggestions?<br>
<br>
<blockquote cite="mid:562E8B8C.10305@oracle.com" type="cite"> <br>
3. There are some white-spaces after the 'level' ([info ]),
it'd be good if those can be removed.<br>
</blockquote>
<br>
This is from the logging framework and not part of the GC log
implementation. I think you need to bring this up on the
serviceability list.<br>
<br>
<br>
<blockquote cite="mid:562E8B8C.10305@oracle.com" type="cite"> <br>
<b>-Xlog:gc*</b><b>:</b><br>
<br>
1. Is there a specific reason to print the tag (gc) and other
sub-tags in different order? For example, we have 'start, gc',
and the order is different in 'gc, heap'.<br>
<i><a moz-do-not-send="true">
<pre>[1.300s][info ][start,gc ] GC#3 GC (Allocation Failure) DefNew start
[1.300s][info ][start,gc ] GC#4 Full GC (Allocation Failure) start
[2.154s][info ][gc ] GC#4 Full GC (Allocation Failure) end 93M->59M(123M) (1.300s, 2.154s) 854.130ms
[2.154s][info ][gc,heap ] GC#3 def new generation: 36767K->0K(39296K)
[2.154s][info ][gc,heap ] GC#3 tenured generation: 58893K->61204K(87424K)
[2.154s][info ][gc,metaspace] GC#3 Metaspace: 2953K->2953K(1056768K)</pre>
</a></i>if possible, I think we should have the order
'main-tag, sub-tag' at all the places.<br>
</blockquote>
<br>
Very well spotted! There is a technical reason for this. I have
been trying to work around it but for now the simplest solution
was to have the start tag first.<br>
<br>
The technical reason is that the "start" tag is added to any
other tags for the timing class that is used to track the time
for a GC (or a GC sub event). Currently the only way to add an
extra tag is to do it at the beginning of the tag set.<br>
<br>
I can try to work around this, or try to get the unified logging
framework to let me append a tag instead. But if it is ok I'd
like to leave it like this for now and file an RFE to fix this
later.<br>
</blockquote>
<br>
I've found a workaround for this issue. Now the start tag is added
at the end of the list:<br>
<tt><br>
</tt><tt>[1.504s][info ][gc,start ] GC#3 GC (Allocation
Failure) DefNew (1.504s)</tt><tt><br>
</tt><tt>[1.504s][info ][gc,start ] GC#4 Full GC (Allocation
Failure) (1.504s)</tt><tt><br>
</tt><tt>[2.368s][info ][gc ] GC#4 Full GC (Allocation
Failure) end 93M->59M(123M) (1.504s, 2.368s) 864.403ms</tt><tt><br>
</tt><tt>[2.368s][info ][gc,heap ] GC#3 def new generation:
36839K->0K(39296K)</tt><tt><br>
</tt><tt>[2.368s][info ][gc,heap ] GC#3 tenured generation:
58872K->61221K(87424K)</tt><tt><br>
</tt><tt>[2.368s][info ][gc,metaspace] GC#3 Metaspace:
2953K->2953K(1056768K)</tt><tt><br>
</tt><tt>[2.368s][info ][gc ] GC#3 GC (Allocation
Failure) DefNew end 93M->59M(123M) (1.504s, 2.368s) 864.653ms</tt><tt><br>
</tt><tt>[2.368s][info ][gc,cpu ] GC#3 CPU Times:
user=0.86s sys=0.00s real=0.86s</tt><br>
<br>
<br>
I've also included the start time stamp in the "start" logging
line.<br>
</blockquote>
<br>
This looks good!<br>
<br>
Thanks,<br>
Poonam<br>
<br>
<blockquote cite="mid:562F4430.3010301@oracle.com" type="cite"> <br>
Thanks,<br>
Bengt<br>
<br>
<blockquote cite="mid:562F1837.6000203@oracle.com" type="cite"> <br>
Thanks,<br>
Bengt<br>
<br>
<blockquote cite="mid:562E8B8C.10305@oracle.com" type="cite"> <br>
Thanks,<br>
Poonam<br>
<br>
<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>
</body>
</html>