GC Metaspace printing after full gc

From an email from nijiaben on the GC-hotspot list (http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2018-September/023329.html):

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.