El Psy Congroo

JAXB导致的Metaspace OOM问题分析

Posted on

最近生产服务器从JDK 7升级到了JDK 8，运行一段时间后发现一台服务器出现了java.lang.OutOfMemoryError: Metaspace错误。这个角色的服务器在使用JDK 7时设置的MaxPermSize是256M，实际使用在100M左右，因此虽然JDK 8的Metaspace可以不设置最大值，但为了防止类似classloader leak的问题导致系统内存耗尽，我们还是设置了512M的限制。由于代码没有变更过，因此怀疑是JDK 8的Metaspace回收机制有变化导致了OOM。

故障分析

分析GC日志

出现OOM异常时，系统一直在进行Full GC (Metadata GC Threshold)，但Metaspace空间始终无法回收

MAT(Eclipse Memory Analyzer)分析Heap Dump

MAT分析Metaspace的手段比较有限，从Class Loader Explorer看起来classloader数量，defined class数量都在合理范围内

分析运行时数据

jcmd提供了多种分析Metaspace的手段，包括

  • VM.native_memory，通过-XX:NativeMemoryTracking=summary启用，分类汇总Native Memory的使用量
  • GC.class_stats，通过-XX:+UnlockDiagnosticVMOptions启用，打印所有class信息

修改JVM启动参数运行一段时间后，通过VM.native_memory发现，大部分内存占用都在Class上
通过GC.class_stats可以看到class数量在不停增长，简单统计后，发现是同一个类com.foo.Bar$JaxbAccessorF_baz的数量在不停增长，从class_stats里可以看出这个类的父类是com.sun.xml.bind.v2.runtime.reflect.Accessor，怀疑是JAXB的bug，尝试google下，发现的确有相关的jira，JAXB-564 Reflection Injector for Optimisation Loosing Previously Defined Classes)，StackOverflow上也有人反馈类似问题Old JaxB and JDK8 Metaspace OutOfMemory Issue

JAXB Bug分析

JAXB为了避免每次通过反射去访问对象属性或者方法，会为属性和方法动态生成Accessor类，并通过Injector对象进行管理

1
2
private static final Map<ClassLoader,WeakReference<Injector>> injectors =
        Collections.synchronizedMap(new WeakHashMap<ClassLoader,WeakReference<Injector>>());

Injector是通过WeakHashMap进行缓存的，GC以后，Injector就被回收了，因此后续访问时就无法获取到生成过的Accessor类，于是JAXB会重新创建一个Injector再次动态生成Accessor类，然而classloader中这个对应的Accessor类已经存在，因此会报LinkageError

1
java.lang.LinkageError: loader (instance of  sun/misc/Launcher$AppClassLoader): attempted  duplicate class definition for name: "com/foo/bar/Baz$JaxbAccessorF_somefield"

修复方式也比较简单，即生成Accessor类前先去classloader里查找下是否已经生成过，具体可以看一下Patch代码

故障重现

为了验证是否是重复定义类造成的OOM，我们尝试下重现故障，重复加载当前package下Foo这个类，使用默认的并发收集器，并限制Permgen/Metaspace为20MB，测试代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
public static void main(String[] args) throws Exception {
   Method defineClass = ClassLoader.class.getDeclaredMethod(
           "defineClass", String.class, byte[].class, Integer.TYPE, Integer.TYPE);
   defineClass.setAccessible(true);
   ClassLoader cl = ClassLoader.getSystemClassLoader();
   String classAsPath = Foo.class.getName().replace('.', '/') + ".class";
   InputStream stream = cl.getResourceAsStream(classAsPath);
   byte[] image = IOUtils.toByteArray(stream);
   while (true) {
       try {
           Class c = (Class) defineClass.invoke(cl, "com.test.Foo", image, 0, image.length);
       } catch (IllegalAccessException | InvocationTargetException e) {
           // e.printStackTrace();
       }
       TimeUnit.MILLISECONDS.sleep(1L);
   }
}

JDK 7 运行结果

1
23.007: [Full GC [PSYoungGen: 2560K->0K(76800K)] [ParOldGen: 8K->961K(67072K)] 2568K->961K(143872K) [PSPermGen: 20479K->4116K(20480K)], 0.0113200 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

JDK 8 运行结果

1
84.960: [Full GC (Metadata GC Threshold) [PSYoungGen: 0K->0K(1397248K)] [ParOldGen: 2876K->2876K(2796544K)] 2876K->2876K(4193792K), [Metaspace: 19588K->19588K(1060864K)], 0.0075317 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
# Class部分committed不断上涨
$ jcmd 62033 VM.native_memory
62033:
Native Memory Tracking:
Total: reserved=5710329KB, committed=365629KB
-                 Java Heap (reserved=4194304KB, committed=154624KB)
                            (mmap: reserved=4194304KB, committed=154624KB)
-                     Class (reserved=1068183KB, committed=23447KB)
                            (classes #10578)
                            (malloc=9367KB #381)
                            (mmap: reserved=1058816KB, committed=14080KB)
1
2
3
4
5
6
# com.test.Foo数量不断增加
$ jcmd 62033 GC.class_stats | awk '{print $13}' | sort | uniq -c | sort -nrk1 | head
  10242 com.test.Foo
      3
      2 ClassName
      1 sun.util.resources.en.TimeZoneNames_en

结论

从重现过程中可以看出，虽然类定义失败了，但过程中产生的数据似乎并没有被清理。在JDK 7中，对Permgen中对象的回收会进行存活性检查，因此重复定义时产生的数据会在GC时被清理。然而在JDK 8中，Metaspace的回收只依赖classloader的存活，当classloader还活着时，它所产生的对象无论存活与否都不会被回收，由此引发了OOM。