A Bug Of Metaspace After Full GC
Stefan Johansson
stefan.johansson at oracle.com
Wed Sep 26 08:06:43 UTC 2018
Thanks for taking care of this JC,
I think it's worth fixing, so please create a webrev and send out an
RFR. Looking a bit more at the code, maybe we should move both the heap
printing and metaspace printing to after the update call, just to keep
the printing together.
Cheers,
Stefan
On 2018-09-25 22:22, JC Beyler wrote:
> I did say I was not a GC expert :-)
>
> So the question would be: is the patch I showed based on Nijiaben's
> patch worth fixing and is it right? It seems like the right thing to do
> for at least fixing SerialGC printouts, no?
> Jc
>
> Ps: here is the patch for simplifying things for everyone then:
> diff -r 8f66a57054b7 src/hotspot/share/gc/shared/genCollectedHeap.cpp
> --- a/src/hotspot/share/gc/shared/genCollectedHeap.cpp Tue Sep 25
> 10:30:32 2018 -0700
> +++ b/src/hotspot/share/gc/shared/genCollectedHeap.cpp Tue Sep 25
> 12:50:54 2018 -0700
> @@ -649,7 +649,6 @@
> complete = complete || collected_old;
> print_heap_change(young_prev_used, old_prev_used);
> - MetaspaceUtils::print_metaspace_change(metadata_prev_used);
> // Adjust generation sizes.
> if (collected_old) {
> @@ -665,6 +664,7 @@
> MetaspaceGC::compute_new_size();
> update_full_collections_completed();
> }
> + MetaspaceUtils::print_metaspace_change(metadata_prev_used);
> // Track memory usage and detect low memory after GC finishes
> MemoryService::track_memory_usage();
>
> On Tue, Sep 25, 2018 at 1:08 PM Krystal Mok <rednaxelafx at gmail.com
> <mailto:rednaxelafx at gmail.com>> wrote:
>
> Hi JC,
>
> Just a quick comment on:
>
> So I looked at the other ones as well and as a summary:
> - The bug seems to show up for Serial, CMS
> - The bug does not seem to show up for Parallel, G1
>
> 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.
> 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.
>
> 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.
>
> - Kris
>
> On Tue, Sep 25, 2018 at 12:57 PM, JC Beyler <jcbeyler at google.com
> <mailto:jcbeyler at google.com>> wrote:
>
> Hi Nijiaben,
>
> I'm not a GC engineer but thought I would look at this by
> curiosity (for note, I also created
> https://bugs.openjdk.java.net/browse/JDK-8211123 for tracking
> purposes). It seems you are using an older JDK because the code
> has changed somewhat there.
>
> I looked at this and used your reproducer on JDK12 tip:
>
> Using CMS (which is being deprecated from what I know and see in
> the log message):
> $
> ~/mercurial/jdk12-gc-print/build/linux-x86_64-server-release/images/jdk/bin/java
> -XX:+UseConcMarkSweepGC -Xmx1000M -Xms1000M -Xlog:gc*
> ClassLoaderTest
> OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was
> deprecated in version 9.0 and will likely be removed in a future
> release.
> ...
> [0.559s][info][gc,metaspace ] GC(0) Metaspace:
> 15267K->15267K(1067008K)
>
> (Note: I am using -Xlog:gc* since -XX:+PrintGCDetails is being
> deprecated as well from what the log message is saying)
>
> So the bug is there for CMS, but for G1, it seems to work:
>
> $
> ~/mercurial/jdk12-gc-print/build/linux-x86_64-server-release/images/jdk/bin/java
> -Xmx1000M -Xms1000M -Xlog:gc* ClassLoaderTest
> ...
> [0.653s][info][gc,metaspace ] GC(0) Metaspace:
> 15266K->5266K(1062912K)
> ...
>
> So I looked at the other ones as well and as a summary:
> - The bug seems to show up for Serial, CMS
> - The bug does not seem to show up for Parallel, G1
>
>
> 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:
>
> diff -r 8f66a57054b7
> src/hotspot/share/gc/shared/genCollectedHeap.cpp
> --- a/src/hotspot/share/gc/shared/genCollectedHeap.cpp Tue Sep
> 25 10:30:32 2018 -0700
> +++ b/src/hotspot/share/gc/shared/genCollectedHeap.cpp Tue Sep
> 25 12:50:54 2018 -0700
> @@ -649,7 +649,6 @@
> complete = complete || collected_old;
> print_heap_change(young_prev_used, old_prev_used);
> - MetaspaceUtils::print_metaspace_change(metadata_prev_used);
> // Adjust generation sizes.
> if (collected_old) {
> @@ -665,6 +664,7 @@
> MetaspaceGC::compute_new_size();
> update_full_collections_completed();
> }
> + MetaspaceUtils::print_metaspace_change(metadata_prev_used);
> // Track memory usage and detect low memory after GC finishes
> MemoryService::track_memory_usage();
>
> With this, I looked at the various GC results and this fixes:
> - Serial, CMS; while keeping Parallel and G1 working (seemingly)
>
> Finally, note that all GC logging now are logging the summary at
> the exit and this line shows up:
> [0.560s][info][gc,heap,exit ] Metaspace used 5277K,
> capacity 5310K, committed 15232K, reserved 1062912K
>
> For all GCs, so though the line "Metaspace before -> after" is
> false, you can get the the after with the final line.
>
> 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.
>
> Hoping that helps,
> Jc
>
>
>
> On Fri, Sep 21, 2018 at 11:56 PM nijiaben <nijiaben at perfma.com
> <mailto:nijiaben at perfma.com>> wrote:
>
> Hi, all
>
> 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.
>
> 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.
>
> Demo：
>
> |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/repository/org/slf4j/slf4j-api/1.7.21/slf4j-api-1.7.21.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.Logger", false, ucl); } catch
> (Exception e) { e.printStackTrace(); } } }|
>
> 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
>
> |-Xmx1000M -Xms1000M -XX:+UseConcMarkSweepGC
> -XX:+PrintGCDetails ClassLoaderTest|
>
> The GC log is
>
> |[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]|
>
> Let's look at the source code of hotspot,
>
> |GenCollectedHeap::do_collection|:
>
> |if (PrintGCDetails) { print_heap_change(gch_prev_used); //
> Print metaspace info for full GC with PrintGCDetails flag.
> if (complete) {
> MetaspaceAux::print_metaspace_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(); // Resize the metaspace
> capacity after full collections
> MetaspaceGC::compute_new_size();
> update_full_collections_completed(); }|
>
> We see that metaspace's gc log output is executed
> before|ClassLoaderDataGraph::purge();|, 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.
>
> 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|ClassLoaderDataGraph::purge()|，just
> like this:
>
> |if (PrintGCDetails) { print_heap_change(gch_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(); // Resize the metaspace
> capacity after full collections
> MetaspaceGC::compute_new_size();
> update_full_collections_completed(); if (PrintGCDetails) {
> // Print metaspace info for full GC with PrintGCDetails
> flag.
> MetaspaceAux::print_metaspace_change(metadata_prev_used); } }|
>
> At this point we recompile hotspot, execute the above demo
> again, you can see the correct output as follows
>
> |[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]|
>
> 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:
>
> |if (PrintGCDetails) { print_heap_change(gch_prev_used); //
> Print perm gen info for full GC with PrintGCDetails flag. if
> (complete) { print_perm_heap_change(perm_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_completed(); }|
>
> It can be seen that the GC engineer at that time simply
> replaced|print_perm_heap_change(perm_prev_used);|with|MetaspaceAux::print_metaspace_change(metadata_prev_used);|but
> forgot the difference between Perm and Metaspace.
>
> Thanks,
>
> nijiaben
>
> ____
>
>
>
> --
>
> Thanks,
> Jc
>
>
>
>
> --
>
> Thanks,
> Jc
More information about the hotspot-gc-dev
mailing list