<div dir="ltr"><div dir="ltr"><div dir="ltr">Hi JC,<div><br></div><div>Just a quick comment on:</div><div><br></div><div><div>So I looked at the other ones as well and as a summary:</div><div> - The bug seems to show up for Serial, CMS</div><div> - The bug does not seem to show up for Parallel, G1</div></div><div><br></div><div>That's because Serial (DefNew) / Serial Old (Tenured / GenMarkSweep) / ParNew / CMS use the "generational GC framework" that's been there for years. That's the "GenCollectedHeap" touched by Nijiaben's propsed patch.</div><div>It was there with the idea that different GC implementations can plug into the same framework and supposedly they could mix-and-match. But later on only a few possible configurations were really tested well and supported.<br></div><div><br></div><div>Parallel (ParallelScavenge) / Parallel Old and G1 use their own implementation of the CollectedHeap interface and doesn't participate in that "generational GC framework". So they don't have the same bug at the same place.</div><div><br></div><div>- Kris</div></div></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Sep 25, 2018 at 12:57 PM, JC Beyler <span dir="ltr"><<a href="mailto:jcbeyler@google.com" target="_blank">jcbeyler@google.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr">Hi Nijiaben,<div><br></div><div>I'm not a GC engineer but thought I would look at this by curiosity (for note, I also created <a href="https://bugs.openjdk.java.net/browse/JDK-8211123" target="_blank">https://bugs.openjdk.<wbr>java.net/browse/JDK-8211123</a> for tracking purposes). It seems you are using an older JDK because the code has changed somewhat there.</div><div><br></div><div>I looked at this and used your reproducer on JDK12 tip:<br></div><div><br></div><div>Using CMS (which is being deprecated from what I know and see in the log message):</div><div><div>$ ~/mercurial/jdk12-gc-print/<wbr>build/linux-x86_64-server-<wbr>release/images/jdk/bin/java -XX:+UseConcMarkSweepGC -Xmx1000M -Xms1000M -Xlog:gc* ClassLoaderTest </div><div>OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.</div><div>...</div><div>[0.559s][info][gc,metaspace ] GC(0) Metaspace: 15267K->15267K(1067008K)</div></div><div><br></div><div>(Note: I am using -Xlog:gc* since -XX:+PrintGCDetails is being deprecated as well from what the log message is saying)</div><div><br></div><div>So the bug is there for CMS, but for G1, it seems to work:</div><div><br></div><div><div>$ ~/mercurial/jdk12-gc-print/<wbr>build/linux-x86_64-server-<wbr>release/images/jdk/bin/java -Xmx1000M -Xms1000M -Xlog:gc* ClassLoaderTest </div></div><div>...</div><div><div>[0.653s][info][gc,metaspace ] GC(0) Metaspace: 15266K->5266K(1062912K)</div></div><div>...</div><div><br></div><div>So I looked at the other ones as well and as a summary:<br></div><div> - The bug seems to show up for Serial, CMS</div><div> - The bug does not seem to show up for Parallel, G1</div><div><br></div><div><br></div><div>I then updated the code like what you were showing though things have changed in tip so my change became a simple one-line move:<br></div><div><div><br></div><div>diff -r 8f66a57054b7 src/hotspot/share/gc/shared/<wbr>genCollectedHeap.cpp</div><div>--- a/src/hotspot/share/gc/shared/<wbr>genCollectedHeap.cpp Tue Sep 25 10:30:32 2018 -0700</div><div>+++ b/src/hotspot/share/gc/shared/<wbr>genCollectedHeap.cpp Tue Sep 25 12:50:54 2018 -0700</div><div>@@ -649,7 +649,6 @@</div><div> complete = complete || collected_old;</div><div> </div><div> print_heap_change(young_prev_<wbr>used, old_prev_used);</div><div>- MetaspaceUtils::print_<wbr>metaspace_change(metadata_<wbr>prev_used);</div><div> </div><div> // Adjust generation sizes.</div><div> if (collected_old) {</div><div>@@ -665,6 +664,7 @@</div><div> MetaspaceGC::compute_new_<wbr>size();</div><div> update_full_collections_<wbr>completed();</div><div> }</div><div>+ MetaspaceUtils::print_<wbr>metaspace_change(metadata_<wbr>prev_used);</div><div> </div><div> // Track memory usage and detect low memory after GC finishes</div><div> MemoryService::track_memory_<wbr>usage();</div></div><div><br></div><div>With this, I looked at the various GC results and this fixes:<br></div><div> - Serial, CMS; while keeping Parallel and G1 working (seemingly)</div><div><br></div><div>Finally, note that all GC logging now are logging the summary at the exit and this line shows up:</div><div>[0.560s][info][gc,heap,exit ] Metaspace used 5277K, capacity 5310K, committed 15232K, reserved 1062912K<br></div><div><br></div><div>For all GCs, so though the line "Metaspace before -> after" is false, you can get the the after with the final line.</div><div><br></div><div>If the GC experts on this list want me to make a webrev out of this and get reviews for it, I can do that.</div><div><br></div><div>Hoping that helps,</div><div>Jc</div><div><br></div><div><br></div></div></div></div></div></div></div></div></div><div class="HOEnZb"><div class="h5"><br><div class="gmail_quote"><div dir="ltr">On Fri, Sep 21, 2018 at 11:56 PM nijiaben <<a href="mailto:nijiaben@perfma.com" target="_blank">nijiaben@perfma.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><p style="margin-right:0px;margin-bottom:15px;margin-left:0px;font-family:Helvetica,arial,sans-serif;margin-top:0px!important">Hi, all</p><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">We use metaspace instead of perm since JDK8, I found that after the Full GC, the size of the metaspace has always been the same from the GC log. I have looked at the source code of hotspot roughly. It has not bean fixed in the latest version. The problem which may have some impact on us to troubleshoot some metaspace problems.<span class="m_6753735621939641654m_3843646335480705488Apple-converted-space"> </span></p><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">I wrote a test case, and simply analyzed the hotspot code, and showed the output before and after the modification. I hope this problem can be fixed as soon as possible.</p><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">Demo：</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial">import java.io.File;
import java.net.URL;
import java.net.URLClassLoader;
/**
*
* @author nijiaben
* @version v1.0
* @createTime 2018年09月22日 12:32:32 PM
*
*/
public class ClassLoaderTest {
private static URL[] urls = new URL[1];
static {
try {
File jarFile = new File("/home/admin/.m2/<wbr>repository/org/slf4j/slf4j-<wbr>api/1.7.21/slf4j-api-1.7.21.<wbr>jar");
urls[0] = jarFile.toURI().toURL();
} catch (Exception e) {
e.printStackTrace();
}
}
public static void main(String args[]) {
for(int i=0;i<1000;i++) {
loadClass();
}
System.gc();
}
public static void loadClass() {
try {
URLClassLoader ucl = new URLClassLoader(urls);
Class.forName("org.slf4j.<wbr>Logger", false, ucl);
} catch (Exception e) {
e.printStackTrace();
}
}
}</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">My demo is very simple, just constantly create a new class loader to load a specific class, after loading, execute a System GC, so that we can see the relevant GC log output, the JVM parameters we run are</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial">-Xmx1000M -Xms1000M -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails ClassLoaderTest</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">The GC log is</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial">[Full GC (System.gc()) [CMS: 0K->9921K(683264K), 0.1003988 secs] 49083K->9921K(989952K), [Metaspace: 12916K->12916K(1064960K)], 0.1060065 secs] [Times: user=0.06 sys=0.05, real=0.11 secs]</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">Let's look at the source code of hotspot,</p><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif"><code style="margin:0px 2px;padding:0px 5px;white-space:nowrap;border:1px solid rgb(234,234,234);background-color:rgb(248,248,248);border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px">GenCollectedHeap::do_<wbr>collection</code>:</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial">if (PrintGCDetails) {
print_heap_change(gch_prev_<wbr>used);
// Print metaspace info for full GC with PrintGCDetails flag.
if (complete) {
MetaspaceAux::print_metaspace_<wbr>change(metadata_prev_used);
}
}
for (int j = max_level_collected; j >= 0; j -= 1) {
// Adjust generation sizes.
_gens[j]->compute_new_size();
}
if (complete) {
// Delete metaspaces for unloaded class loaders and clean up loader_data graph
ClassLoaderDataGraph::purge();
MetaspaceAux::verify_metrics()<wbr>;
// Resize the metaspace capacity after full collections
MetaspaceGC::compute_new_size(<wbr>);
update_full_collections_<wbr>completed();
}</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">We see that metaspace's gc log output is executed before<span class="m_6753735621939641654m_3843646335480705488Apple-converted-space"> </span><code style="margin:0px 2px;padding:0px 5px;white-space:nowrap;border:1px solid rgb(234,234,234);background-color:rgb(248,248,248);border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px">ClassLoaderDataGraph::<wbr>purge();<span class="m_6753735621939641654m_3843646335480705488Apple-converted-space"> </span></code>, that means the size of the metaspace is printed without reclaiming the memory of the metaspace, so the GC log seems no change before and after the GC metaspace.</p><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">After knowing the specific problem, we can make an adjustment to the code to move the logic of the output of metaspace size after to<span class="m_6753735621939641654m_3843646335480705488Apple-converted-space"> </span><code style="margin:0px 2px;padding:0px 5px;white-space:nowrap;border:1px solid rgb(234,234,234);background-color:rgb(248,248,248);border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px">ClassLoaderDataGraph::<wbr>purge()</code>，just like this:</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial"> if (PrintGCDetails) {
print_heap_change(gch_prev_<wbr>used);
}
for (int j = max_level_collected; j >= 0; j -= 1) {
// Adjust generation sizes.
_gens[j]->compute_new_size();
}
if (complete) {
// Delete metaspaces for unloaded class loaders and clean up loader_data graph
ClassLoaderDataGraph::purge();
MetaspaceAux::verify_metrics()<wbr>;
// Resize the metaspace capacity after full collections
MetaspaceGC::compute_new_size(<wbr>);
update_full_collections_<wbr>completed();
if (PrintGCDetails) {
// Print metaspace info for full GC with PrintGCDetails flag.
MetaspaceAux::print_metaspace_<wbr>change(metadata_prev_used);
}
}</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">At this point we recompile hotspot, execute the above demo again, you can see the correct output as follows</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial">[Full GC (System.gc()) [CMS: 0K->9921K(683264K), 0.0852627 secs] 49083K->9921K(989952K), [Metaspace: 12913K->3280K(1058816K)], 0.0891207 secs] [Times: user=0.05 sys=0.04, real=0.09 secs]</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">I also probably thought about why this problem is caused. This is the version before JDK8, such as JDK7, you can see the same code location:</p><div style="font-family:Helvetica,arial,sans-serif"><pre style="margin-top:15px;margin-bottom:15px;background-color:rgb(248,248,248);border:1px solid rgb(204,204,204);font-size:13px;line-height:19px;overflow:auto;padding:6px 10px;border-radius:3px"><code class="m_6753735621939641654m_3843646335480705488language-none" style="margin:0px;padding:0px;white-space:pre-wrap;border:none;background-color:transparent;border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px;background-position:initial initial;background-repeat:initial initial">if (PrintGCDetails) {
print_heap_change(gch_prev_<wbr>used);
// Print perm gen info for full GC with PrintGCDetails flag.
if (complete) {
print_perm_heap_change(perm_<wbr>prev_used);
}
}
for (int j = max_level_collected; j >= 0; j -= 1) {
// Adjust generation sizes.
_gens[j]->compute_new_size();
}
if (complete) {
// Ask the permanent generation to adjust size for full collections
perm()->compute_new_size();
update_full_collections_<wbr>completed();
}</code></pre></div><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">It can be seen that the GC engineer at that time simply replaced<span class="m_6753735621939641654m_3843646335480705488Apple-converted-space"> </span><code style="margin:0px 2px;padding:0px 5px;white-space:nowrap;border:1px solid rgb(234,234,234);background-color:rgb(248,248,248);border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px">print_perm_heap_<wbr>change(perm_prev_used);</code>with<span class="m_6753735621939641654m_3843646335480705488Apple-converted-space"> </span><code style="margin:0px 2px;padding:0px 5px;white-space:nowrap;border:1px solid rgb(234,234,234);background-color:rgb(248,248,248);border-top-left-radius:3px;border-top-right-radius:3px;border-bottom-right-radius:3px;border-bottom-left-radius:3px">Me<wbr>taspaceAux::print_metaspace_<wbr>change(metadata_prev_used);</code>but forgot the difference between Perm and Metaspace.</p><p style="margin:15px 0px;font-family:Helvetica,arial,sans-serif">Thanks,</p><p style="margin-top:15px;margin-right:0px;margin-left:0px;font-family:Helvetica,arial,sans-serif;margin-bottom:0px!important">nijiaben</p></div><div><u></u><u></u></div></blockquote></div><br clear="all"><div><br></div></div></div><span class="HOEnZb"><font color="#888888">-- <br><div dir="ltr" class="m_6753735621939641654gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div><br></div>Thanks,<div>Jc</div></div></div>
</font></span></blockquote></div><br></div>