<html>
<head>
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
</head>
<body text="#000000" bgcolor="#FFFFFF">
<br>
Hi Jon,<br>
<br>
<div class="moz-cite-prefix">On 2016-02-04 20:39, Jon Masamitsu
wrote:<br>
</div>
<blockquote cite="mid:56B3A8DC.3080305@oracle.com" type="cite">
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
<font face="Times New Roman, Times, serif">Bengt,<br>
<br>
The changes look good.<br>
</font></blockquote>
<br>
Thanks for looking at this!<br>
<br>
<br>
<blockquote cite="mid:56B3A8DC.3080305@oracle.com" type="cite"><font
face="Times New Roman, Times, serif"> <br>
Is it correct that for </font><br>
<pre>PSParallelCompact::invoke_no_policy()
the VerifyBeforeGC is now done before the
heap dump? That seems like the right order
but I thought I would note that change.</pre>
</blockquote>
<br>
Yes, that is a correct observation. This is similar to what
PSMarkSweep::invoke_no_policy() and
G1CollectedHeap::do_full_collection() already did. So, I think this
change just makes all GCs work similarly in that sense. If we would
like to change that order I would prefer to do it as a separate
change for all GCs.<br>
<br>
Thanks,<br>
Bengt<br>
<br>
<blockquote cite="mid:56B3A8DC.3080305@oracle.com" type="cite">
<pre>
Jon
</pre>
<br>
<div class="moz-cite-prefix">On 02/04/2016 07:26 AM, Bengt
Rutisson wrote:<br>
</div>
<blockquote cite="mid:56B36D8D.6020905@oracle.com" type="cite"> <br>
Hi everyone, <br>
<br>
Could I have a couple of reviews for this change? <br>
<br>
<a moz-do-not-send="true" class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Ebrutisso/8149035/webrev.00/">http://cr.openjdk.java.net/~brutisso/8149035/webrev.00/</a>
<br>
<a moz-do-not-send="true" class="moz-txt-link-freetext"
href="https://bugs.openjdk.java.net/browse/JDK-8149035">https://bugs.openjdk.java.net/browse/JDK-8149035</a>
<br>
<br>
There are two actions that can be taken before and after a full
GC. We can do a a heap dump and we can produce a class
histogram. <br>
<br>
Both these actions now use their own GC ID and are logged and
recorded as separate GCs. It is more natural that they are
considered part of the full GC. Especially since they make up a
significant part of the pause that the application experience. <br>
<br>
We should move these two actions inside of the GC pause
reporting. <br>
<br>
The log now looks like this (truncated the class histogram for
readability): <br>
<br>
[1,930s][info ][gc,start ] GC(1) Pause Full (System.gc())
(1,930s) <br>
[1,930s][info ][gc,start ] GC(1) Heap Dump (before full gc)
(1,930s) <br>
[1,985s][info ][gc ] GC(1) Heap Dump (before full gc)
(1,930s, 1,985s) 54,830ms <br>
[1,994s][trace ][gc,classhisto] GC(1) num #instances
#bytes class name <br>
[1,994s][trace ][gc,classhisto] GC(1)
---------------------------------------------- <br>
[1,994s][trace ][gc,classhisto] GC(1) 1: 9059
601136 [B <br>
[1,994s][trace ][gc,classhisto] GC(1) 2: 466 480144
[I <br>
[1,994s][trace ][gc,classhisto] GC(1) 3: 1788
205608 java.lang.Class <br>
... <br>
[1,999s][trace ][gc,classhisto] GC(1) 584: 1 16
sun.util.resources.cldr.provider.CLDRLocaleDataMetaInfo_jdk_localedata
<br>
[1,999s][trace ][gc,classhisto] GC(1) Total 40164
2413832 <br>
[1,999s][trace ][gc,classhisto] GC(1) Class Histogram (before
full gc) (1,985s, 1,999s) 13,485ms <br>
[2,051s][info ][gc,heap ] GC(1) PSYoungGen:
2349K->0K(57344K) <br>
[2,051s][info ][gc,heap ] GC(1) ParOldGen:
8K->1902K(65536K) <br>
[2,051s][info ][gc,metaspace ] GC(1) Metaspace:
10738K->10738K(1058816K) <br>
[2,062s][trace ][gc,classhisto] GC(1) num #instances
#bytes class name <br>
[2,062s][trace ][gc,classhisto] GC(1)
---------------------------------------------- <br>
[2,062s][trace ][gc,classhisto] GC(1) 1: 9059
601136 [B <br>
[2,062s][trace ][gc,classhisto] GC(1) 2: 1788
205608 java.lang.Class <br>
[2,062s][trace ][gc,classhisto] GC(1) 3: 8551
205224 java.lang.String <br>
... <br>
[2,067s][trace ][gc,classhisto] GC(1) 584: 1 16
sun.util.resources.cldr.provider.CLDRLocaleDataMetaInfo_jdk_localedata
<br>
[2,067s][trace ][gc,classhisto] GC(1) Total 40093
1948480 <br>
[2,067s][trace ][gc,classhisto] GC(1) Class Histogram (after
full gc) (2,051s, 2,067s) 16,486ms <br>
[2,067s][info ][gc ] GC(1) Pause Full (System.gc())
2M->1M(120M) (1,930s, 2,067s) 137,013ms <br>
[2,067s][info ][gc,cpu ] GC(1) User=0,87s Sys=0,03s
Real=0,14s <br>
<br>
Several things had to be fixed for this to work properly: <br>
<br>
- The calls to pre/post_full_gc_dump() in genCollectedHeap.cpp
were moved to concurrentMarkSweepGeneration.cpp and
tenuredGeneration.cpp <br>
- In psMarkSweep and parallelCompact the calls to
pre/post_full_gc_dump() were moved to inside the GC start/end. <br>
- In CollectedHeap::full_gc_dump() the setup of a new GC id was
removed. <br>
- In CollectedHeap::full_gc_dump() the use of FormatBuffer was
removed. This is necessary since the "title" passed to
GCTraceTime is stored and used later to send a trace event. <br>
- In heapInspection.cpp the logging for the title was moved to
be able to use two print_cr calls to make it log the title with
decorations properly. <br>
- A log prefix was added for [gc, classhisto] <br>
<br>
Thanks, <br>
Bengt <br>
</blockquote>
<br>
</blockquote>
<br>
</body>
</html>