JVM实战（28）——模拟Metaspace内存溢出

作者简介：大家好，我是smart哥，前中兴通讯、美团架构师，现某互联网公司CTO

联系qq：184480602，加我进群，大家一起学习，一起进步，一起对抗互联网寒冬

学习必须往深处挖，挖的越深，基础越扎实！

阶段1、深入多线程

阶段2、深入多线程设计模式

阶段3、深入juc源码解析

阶段4、深入jdk其余源码解析

阶段5、深入jvm源码解析

一、简介

本章，我们将通过示例代码演示Metaspace区域是如何发生内存溢出的，并根据内存快照进行分析。

我们回顾下Metaspace区发生内存溢出的一个场景：程序不停的动态生成类，然后不停的加载类到Metaspace区域，而且这些动态生成的类必须得是不能被回收的，一旦Metaspace区满了，就会触发Full GC，而由于Metaspace区中的对象无法被回收，此时就触发了Metaspace内存溢出。

二、示例程序

我们的示例程序采用CGLIB来动态生成类。

2.1 程序源码

    public class Demo1 {
        public static void main(String[] args) {
            long count = 0L;
            while (true) {
                Enhancer enhancer = new Enhancer();
                enhancer.setSuperclass(Car.class);
                enhancer.setUseCache(false);
                enhancer.setCallback(new MethodInterceptor() {
                    public Object intercept(Object o, Method method, Object[] objects, MethodProxy methodProxy) throws Throwable {
                        if (method.getName().equals("run")) {
                            System.out.println("Before run, security checking...");
                            return methodProxy.invokeSuper(o, objects);
                        } else {
                            return methodProxy.invokeSuper(o, objects);
                        }
                    }
                });
    
                Car car = (Car) enhancer.create();
                car.run();
    
                System.out.println("Created " + ++count +" Car.");
            }
        }
    
        static class Car {
            public void run() {
                System.out.println("Car is running...");
            }
        }
    
        static class SafeCar extends Car{
            @Override
            public void run() {
                System.out.println("Car is running...");
                super.run();
            }
        }
    }

上述代码，通过CGLIB的Enhancer生成了一个Car的代理子类：

    Enhancer enhancer = new Enhancer();
    enhancer.setSuperclass(Car.class);
    enhancer.setUseCache(false);

既然是Car的子类，就会有Car的所有方法，然后我们在调用子类的run方法时做了点手脚：

    enhancer.setCallback(new MethodInterceptor() {
        public Object intercept(Object o, Method method, Object[] objects, MethodProxy methodProxy) throws Throwable {
            if (method.getName().equals("run")) {
                System.out.println("Before run, security checking...");
                return methodProxy.invokeSuper(o, objects);
            } else {
                return methodProxy.invokeSuper(o, objects);
            }
        }
    });

上述这段代码的意思是：如果调用了Car子类对象的方法，会先被这里的MethodInterceptor拦截，拦截后判断如果是run方法，则先做一些额外的工作——汽车安全检查，最后再执行父类的run方法。效果等同于：

    static class SubCar extends Car {
        @Override
        public void run() {
            System.out.println("Before run, security checking...");
            super.run();
        }
    }

2.2 JVM参数

接着，我们需要通过JVM参数限制下Metaspace区域的大小，我们把它设置为10MB，然后开启内存溢出时自动dump内存快照：
-XX:MetaspaceSize=10m -XX:MaxMetaspaceSize=10m -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -Xloggc:gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./

使用该参数执行程序，可以看到如下所示的打印输出，当创建到第258辆Car时，Metaspace区的内存被耗尽了，导致java.lang.OutOfMemoryError: Metaspace：

    Created 258 Car.
    java.lang.OutOfMemoryError: Metaspace
    Dumping heap to ./\java_pid11836.hprof ...
    Heap dump file created [3470456 bytes in 0.120 secs]
    Exception in thread "main" net.sf.cglib.core.CodeGenerationException: java.lang.reflect.InvocationTargetException-->null
        at net.sf.cglib.core.AbstractClassGenerator.generate(AbstractClassGenerator.java:348)
        at net.sf.cglib.proxy.Enhancer.generate(Enhancer.java:492)
        at net.sf.cglib.core.AbstractClassGenerator$ClassLoaderData.get(AbstractClassGenerator.java:117)
        at net.sf.cglib.core.AbstractClassGenerator.create(AbstractClassGenerator.java:294)
        at net.sf.cglib.proxy.Enhancer.createHelper(Enhancer.java:480)
        at net.sf.cglib.proxy.Enhancer.create(Enhancer.java:305)
        at com.ressmix.jvm.Demo1.main(Demo1.java:27)
    Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at net.sf.cglib.core.ReflectUtils.defineClass(ReflectUtils.java:459)
        at net.sf.cglib.core.AbstractClassGenerator.generate(AbstractClassGenerator.java:339)
        ... 6 more
    Caused by: java.lang.OutOfMemoryError: Metaspace
        at java.lang.ClassLoader.defineClass1(Native Method)
        at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
        ... 11 more

三、问题分析

上述程序执行完后，会在程序根目录生成两个文件：gc.log和java_pid11836.hprof，gc.log是JVM运行时信息，java_pid11836.hprof就是内存快照。

3.1 GC日志分析

我们先来分析下gc.log：

    1.218: [GC (Allocation Failure) 1.276: [ParNew: 52480K->2051K(59008K), 0.0160380 secs] 52480K->2051K(190080K), 0.0745051 secs] [Times: user=0.05 sys=0.00, real=0.08 secs] 
    1.631: [GC (Allocation Failure) 1.631: [ParNew: 54531K->2855K(59008K), 0.0025661 secs] 54531K->2855K(190080K), 0.0026505 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    1.881: [Full GC (Metadata GC Threshold) 1.881: [CMS: 0K->2708K(131072K), 0.0464583 secs] 36239K->2708K(190080K), [Metaspace: 9885K->9885K(1058816K)], 0.0467198 secs] [Times: user=0.05 sys=0.01, real=0.05 secs] 
    1.927: [Full GC (Last ditch collection) 1.927: [CMS: 2708K->1749K(131072K), 0.0104116 secs] 2708K->1749K(190144K), [Metaspace: 9885K->9885K(1058816K)], 0.0104936 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
    2.012: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1749K(131072K)] 1749K(190144K), 0.0001810 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    2.012: [CMS-concurrent-mark-start]
    2.022: [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
    2.057: [CMS-concurrent-preclean-start]
    2.058: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    Heap
     par new generation   total 59072K, used 1363K [0x0000000701a00000, 0x0000000705a10000, 0x00000007166c0000)
      eden space 52544K,   2% used [0x0000000701a00000, 0x0000000701b54c68, 0x0000000704d50000)
      from space 6528K,   0% used [0x0000000704d50000, 0x0000000704d50000, 0x00000007053b0000)
      to   space 6528K,   0% used [0x00000007053b0000, 0x00000007053b0000, 0x0000000705a10000)
     concurrent mark-sweep generation total 131072K, used 1749K [0x00000007166c0000, 0x000000071e6c0000, 0x00000007c0000000)
     Metaspace       used 9912K, capacity 10090K, committed 10240K, reserved 1058816K
      class space    used 890K, capacity 913K, committed 1024K, reserved 1048576K
    2.063: [GC (CMS Final Remark) [YG occupancy: 1363 K (59072 K)]2.063: [Rescan (parallel) , 0.0002642 secs]2.063: [weak refs processing, 0.0000124 secs]2.063: [class unloading, 0.0012829 secs]2.065: [scrub symbol table, 0.0005776 secs]2.065: [scrub string table, 0.0001698 secs][1 CMS-remark: 1749K(131072K)] 3112K(190144K), 0.0024292 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

先触发了两次Young GC，主要是因为不断创建Car对象，最终Eden区无法容纳。我们关键看下Full GC，第一次Full GC如下：

    1.881: [Full GC (Metadata GC Threshold) 1.881: [CMS: 0K->2708K(131072K), 0.0464583 secs] 36239K->2708K(190080K), [Metaspace: 9885K->9885K(1058816K)], 0.0467198 secs] [Times: user=0.05 sys=0.01, real=0.05 secs]

Metadata GC Threshold告诉我们是因为Metasapce区空间不足而引起Full GC。可以看到，Metasapce区的对象已经快占满了10MB了——[Metaspace: 9885K->9885K(1058816K)]，经过这次Full GC，里面的对象并没有被回收掉，接着就进行下一次Full GC，这是最后的拯救机会（Last ditch collection）：

    1.927: [Full GC (Last ditch collection) 1.927: [CMS: 2708K->1749K(131072K), 0.0104116 secs] 2708K->1749K(190144K), [Metaspace: 9885K->9885K(1058816K)], 0.0104936 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

结果还是一样，Metaspace区中的对象依旧无法回收，也不够容纳新创建的类对象，所以JVM直接终止运行，并打印出最后的堆内存的情况。