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