警惕大量类加载器的创建导致诡异的Full GC原创
概述
今天有个同事找我,其实好像之前就找过我,一直因为太忙,后面就忘记他的事了,到今天还没查出原因就又找了过来,现象是系统老是进行Full GC,在启动没过多久就会发生Full GC,这个现象相对比较少见的,于是找他要了GC日志,赫然看到如下日志:
这个很显然就是达到了Metaspace的阈值触发的Full GC了,但是看看Metaspace的size,使用了134M左右,于是我询问他MetaspaceSize和MaxMetaspaceSize分别设置了多少,告知我设置的是256M,那就有几个比较奇怪的地方了:
- 为什么启动没多久就因为Metaspace触发了Full GC
- 从使用率来看并没有达到阈值
- 在Full GC之后立马就能正常运行一段时间,说明Metaspace确实回收了
先说个JVM的BUG
从上面的GC日志,我们看到了Full GC前后,Metaspace的使用变化是从137752K->71671K,其实你们如果用的oracle官方的JDK,看到的会是137752K->137752K,也就是并没有发生变化,看起来好像Metaspace并没有被回收,其实这是JVM的一个BUG,我们alijdk将这个问题进行了修复,能看到前后是有变化的,所以如果大家在排查Metaspace的问题时候,希望不要被这个信息骗到
再聊点GC日志
从JDK8开始,任何GC,都会默认打印GC Cause,所以你看到上面的Full GC是因为Metadata GC Threshold触发的,也就是Metaspace committed的内存加上这次要分配的内存达到了MetaspaceSize的阈值。如果是JDK7(之前版本不支持),那可以通过加JVM参数-XX:+PrintGCCause来打印原因。
再提一点,Metaspce触发的GC都是Full GC。
另外大家常看到的类似下面的Allocation Failure的GC Cause,其实是正常的,因为大部分GC,尤其是YGC,都是因为分配内存失败才触发的,所以不要认为看到Failure就觉得有问题。
为何使用率这么低就触发了Full GC
Metaspace触发Full GC,是因为Metaspace committed的内存加上这次要分配的内存之和超过了阈值才会触发,但是我们看使用了才134M,而阈值却是256M,那可能怀疑下面两种情况:
这次分配的内存达到122M以上?
碎片化问题?
对于第一种情况,基本不太可能,因为一个类不可能要这么大内存,所以暂时先排除这种可能。
对于第二种情况,有一个场景是能满足的,类加载器创建非常多,但是每个类加载器加载的类又特别少,同时Full GC之后又能很快被回收掉
为了验证第二种情况,我尝试加两个参数-XX:+HeapDumpBeforeFullGC和-XX:+HeapDumpAfterFullGC,在Full GC前后分别对内存做一个dump。
从两个dump的分析结果来看,查了下类加载器的情况,果然在Full GC之前看到了31650个类加载器,而Full GC之后,类加载器个数变成了872个,于是开始找究竟是哪些类加载器,最终发现某个特定类型的类加载器对象非常之多,咨询了业务方确实存在这种情况,因为没有做好缓存,所以导致了无止境创建
类加载器过多为什么会导致Full GC
类加载器创建过多,带来的一个问题是,在类加载器第一次加载类的时候,会在Metaspace里会给它分配内存块,为了分配高效,每个类加载器用来存放类信息的内存块都是独立的,所以哪怕你这个类加载器只加载一个类,也会为之分配一块空的内存给这个类加载器,其实是至少两个内存块,于是你有可能会发现Metaspace的内存使用率非常低,但是committed的内存已经达到了阈值,从而触发了Full GC,如果这种只加载很少类的类加载器非常多,那造成的后果就是很多碎片化的内存