java fgc_java Metaspace频繁FGC问题定位

问题描述

数据服务是通过SQL对外提供数据查询的服务平台，底层存储支持HBase和MySQL两种。用户首先在管理平台上配置好接口的SQL详情

SQL接口配置

业务方通过微服务接口根据生成的ID以及接口参数来完成数据的查询，由于HBase不支持SQL引擎的查询，我们基于calcite实现了一套简单的SQL On HBase解析逻辑。

查看笔者前面的文章可以看到堆空间内存泄露的文章，可以了解相关的详情。但是不巧的是，堆内存泄露问题解决后，更恼火的问题又出现了，这次Old区的频繁GC被解决了，但是有些机器会有Metaspace的FGC出现。没办法，遇到问题解决问题呗，不然还能怎么办？

问题现象描述

程序JVM的启动参数描述如下，其中Metaspace的空间和最大空间均设置为512M，老年代开启CMS的垃圾回收策略。采用的JDK版本是1.8

Java(TM) SE Runtime Environment (build 1.8.0_131-b11)

Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

JVM启动参数:

-Xmn1024m -Xms2500m -Xmx2500m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:MaxDirectMemorySize=512m -XX:+UseCMSInitiatingOccupancyOnly -XX:SurvivorRatio=8 -XX:+ExplicitGCInvokesConcurrent -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:-OmitStackTraceInFastThrow -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/var/www/logs/gc-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/www/logs -Djava.io.tmpdir=/var/www/tmp -Dsaffron.default.charset=UTF-16LE

系统运行一段时间后，GC日志开始频繁出现FGC的情况

2018-10-09T16:18:04.362+0800: 712.106: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:04.362+0800: 712.106: [CMS: 188082K->208919K(1511424K), 0.9099363 secs] 829279K->208919K(2455168K), [Metaspace: 297357K->297357K(1284096K)], 0.9108698 secs] [Times: user=0.90 sys=0.00, real=0.91 secs]

2018-10-09T16:18:05.273+0800: 713.016: [Full GC (Last ditch collection) 2018-10-09T16:18:05.273+0800: 713.017: [CMS: 208919K->199979K(1511424K), 0.7405391 secs] 208919K->199979K(2455168K), [Metaspace: 297357K->297357K(1284096K)], 0.7412885 secs] [Times: user=0.74 sys=0.00, real=0.75 secs]

2018-10-09T16:18:08.263+0800: 716.007: [GC (CMS Initial Mark) [1 CMS-initial-mark: 199979K(1511424K)] 200219K(2455168K), 0.0288286 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

2018-10-09T16:18:08.292+0800: 716.036: [CMS-concurrent-mark-start]

2018-10-09T16:18:08.321+0800: 716.064: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:08.321+0800: 716.064: [CMS2018-10-09T16:18:08.567+0800: 716.311: [CMS-concurrent-mark: 0.251/0.275 secs] [Times: user=0.33 sys=0.01, real=0.28 secs]

(concurrent mode failure): 199979K->199824K(1511424K), 0.9890622 secs] 219148K->199824K(2455168K), [Metaspace: 297368K->297368K(1284096K)], 0.9899682 secs] [Times: user=0.99 sys=0.00, real=0.99 secs]

2018-10-09T16:18:09.311+0800: 717.054: [Full GC (Last ditch collection) 2018-10-09T16:18:09.311+0800: 717.054: [CMS: 199824K->199813K(1511424K), 0.6584775 secs] 199824K->199813K(2455168K), [Metaspace: 297365K->297365K(1284096K)], 0.6591656 secs] [Times: user=0.65 sys=0.00, real=0.66 secs]

2018-10-09T16:18:10.017+0800: 717.760: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:10.017+0800: 717.760: [CMS: 199813K->199737K(1511424K), 0.7314426 secs] 229113K->199737K(2455168K), [Metaspace: 297371K->297371K(1284096K)], 0.7323365 secs] [Times: user=0.72 sys=0.00, real=0.73 secs]

2018-10-09T16:18:10.749+0800: 718.492: [Full GC (Last ditch collection) 2018-10-09T16:18:10.749+0800: 718.493: [CMS: 199737K->199703K(1511424K), 0.6630502 secs] 199737K->199703K(2455168K), [Metaspace: 297368K->297368K(1284096K)], 0.6638106 secs] [Times: user=0.66 sys=0.00, real=0.66 secs]

2018-10-09T16:18:11.417+0800: 719.161: [GC (CMS Initial Mark) [1 CMS-initial-mark: 199703K(1511424K)] 199720K(2455168K), 0.0321014 secs] [Times: user=0.04 sys=0.00, real=0.03 secs]

2018-10-09T16:18:11.450+0800: 719.193: [CMS-concurrent-mark-start]

2018-10-09T16:18:11.462+0800: 719.206: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:11.462+0800: 719.206: [CMS2018-10-09T16:18:11.708+0800: 719.451: [CMS-concurrent-mark: 0.240/0.258 secs] [Times: user=0.28 sys=0.00, real=0.26 secs]

(concurrent mode failure): 199703K->199549K(1511424K), 0.9338810 secs] 203226K->199549K(2455168K), [Metaspace: 297370K->297370K(1284096K)], 0.9347004 secs] [Times: user=0.94 sys=0.00, real=0.94 secs]

2018-10-09T16:18:12.397+0800: 720.140: [Full GC (Last ditch collection) 2018-10-09T16:18:12.397+0800: 720.140: [CMS: 199549K->199549K(1511424K), 0.6567313 secs] 199549K->199549K(2455168K), [Metaspace: 297366K->297366K(1284096K)], 0.6574535 secs] [Times: user=0.64 sys=0.00, real=0.66 secs]

2018-10-09T16:18:13.076+0800: 720.820: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:13.076+0800: 720.820: [CMS: 199549K->199431K(1511424K), 0.7530066 secs] 199994K->199431K(2455168K), [Metaspace: 297366K->297366K(1284096K)], 0.7538338 secs] [Times: user=0.74 sys=0.00, real=0.75 secs]

2018-10-09T16:18:13.830+0800: 721.574: [Full GC (Last ditch collection) 2018-10-09T16:18:13.830+0800: 721.574: [CMS: 199431K->199431K(1511424K), 0.7671261 secs] 199431K->199431K(2455168K), [Metaspace: 297363K->297363K(1284096K)], 0.7678759 secs] [Times: user=0.77 sys=0.00, real=0.77 secs]

2018-10-09T16:18:14.620+0800: 722.363: [GC (CMS Initial Mark) [1 CMS-initial-mark: 199431K(1511424K)] 200758K(2455168K), 0.0258070 secs] [Times: user=0.04 sys=0.00, real=0.03 secs]

从上面的GC日志中反应了好几个问题点？

FGC时显示Metaspace的空间差不多又1.2G,[Metaspace: 297366K->297366K(1284096K)]?明显我们的最大只有512M

就算GC也没达到阈值512M，为什么会GC呢？

2018-10-09T16:18:13.076+0800: 720.820: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:13.076+0800: 720.820: [CMS: 199549K->199431K(1511424K), 0.7530066 secs] 199994K->199431K(2455168K), [Metaspace: 297366K->297366K(1284096K)], 0.7538338 secs] [Times: user=0.74 sys=0.00, real=0.75 secs]

查看相关资料和官方文档后，发现Metaspace还有一个区间是Klass Metaspace，由参数-XX:CompressedClassSpaceSize进行控制，具体的内容大家可以参考寒泉子的JVM源码分析之Metaspace解密文章。JDK1.8下默认是1G，加上NoKlass Metaspace占用的两百多兆，差不多1.2G。

为什么会出发GC呢？也可以参考寒泉子的文章，摘取的重点信息如下：

类加载器创建过多，带来的一个问题是，在类加载器第一次加载类的时候，会在Metaspace里会给它分配内存块，为了分配高效，每个类加载器用来存放类信息的内存块都是独立的，所以哪怕你这个类加载器只加载一个类，也会为之分配一块空的内存给这个类加载器，其实是至少两个内存块，于是你有可能会发现Metaspace的内存使用率非常低，但是committed的内存已经达到了阈值，从而触发了Full GC，如果这种只加载很少类的类加载器非常多，那造成的后果就是很多碎片化的内存

其实就是实际上只是用两百多兆，但是committed的内存已经达到了阈值，触发了GC。

发现Metaspace的空间FGC前后没有发生变化，寒泉子也说过这个是JDK的一个bug，笔者写此篇文章的时候，该patch已经被JDK官方收录。

从上面的GC日志，我们看到了Full GC前后，Metaspace的使用变化是从137752K->71671K，其实你们如果用的oracle官方的JDK，看到的会是137752K->137752K，也就是并没有发生变化，看起来好像Metaspace并没有被回收，其实这是JVM的一个BUG，我们alijdk将这个问题进行了修复，能看到前后是有变化的，所以如果大家在排查Metaspace的问题时候，希望不要被这个信息骗到

但是问题依然存在，因为下一次开始的时候Metaspace空间GC前的还是很大，第一次GC为[Metaspace: 297370K->297370K(1284096K)], 0.9347004 secs]，第二次GC[Metaspace: 297366K->297366K(1284096K)], 0.6574535 secs]，第一次GC后到第二次GC前由达到了297366K，说明Metaspace的空间快速的又被占满了。

2018-10-09T16:18:11.462+0800: 719.206: [Full GC (Metadata GC Threshold) 2018-10-09T16:18:11.462+0800: 719.206: [CMS2018-10-09T16:18:11.708+0800: 719.451: [CMS-concurrent-mark: 0.240/0.258 secs] [Times: user=0.28 sys=0.00, real=0.26 secs]

(concurrent mode failure): 199703K->199549K(1511424K), 0.9338810 secs] 203226K->199549K(2455168K), [Metaspace: 297370K->297370K(1284096K)], 0.9347004 secs] [Times: user=0.94 sys=0.00, real=0.94 secs]

2018-10-09T16:18:12.397+0800: 720.140: [Full GC (Last ditch collection) 2018-10-09T16:18:12.397+0800: 720.140: [CMS: 199549K->199549K(1511424K), 0.6567313 secs] 199549K->199549K(2455168K), [Metaspace: 297366K->297366K(1284096K)], 0.6574535 secs] [Times: user=0.64 sys=0.00, real=0.66 secs]

Metapace主要是类的一些元数据信息，主要来源于类的加载，也可以通过命令jstat -class 命令来查看类的加载和卸载情况，也可以设置 -verbose:gc参数来查看具体的类加载信息。

那具体是用到了哪些类加载器呢？有多种方式可以查看，一种最简单的就是通过jmap -hiso:live 来查看ClassLoader对象较多的类型。另外一种也可以通过MAT工具来查看所有类加载器对象的个数。很容易定位到是ByteArrayClassLoader这个类的对象数量最多，所以接下来只需要找到什么场景下会使用ByteArrayClassLoader来加载类就可以了。

我们由于用了calcite的接口，每次查询的时候都会创建一个新的ByteArrayClassLoader来加载一个新的类，具体堆栈信息可以查看:

堆栈信息

Metaspace中的类信息只有在加载它的ClassLoader被释放后才会发生卸载，如果ClassLoader对象一直存活的时候，那么由它所加载的类的元数据信息也不会被卸载。

再次强调，ByteArrayClassLoader除了被方法的局部变量引用后，并不会被其他对象引用，原则上Metaspace发生FGC后会触发堆区的GC，会释放掉这些ClassLoader，从而Metaspace中的元数据信息也会随着被卸载。然后显示情况很明显不是这样，难道是有对象引用了ByteArrayClassLoder对象了，决定dump下来后分析下内存引用情况，具体的方法前文中已经说明过，在此不再赘述，直接上引用情况。

ByteArrayClassLoder引用情况

可以看到确实只有局部变量有引用，那么问题来了，是什么原因导致的呢？

回顾下对象会被回收的条件：

这个算法的基本思想是通过一系列称为“GC Roots”的对象作为起始点，从这些节点向下搜索，搜索所走过的路径称为引用链，当一个对象到GC Roots没有任何引用链(即GC Roots到对象不可达)时，则证明此对象是不可用的。

那么问题又来了，如何选取GCRoots对象呢？在Java语言中，可以作为GCRoots的对象包括下面几种：

(1). 虚拟机栈(栈帧中的局部变量区，也叫做局部变量表)中引用的对象。

(2). 方法区中的类静态属性引用的对象。

(3). 方法区中常量引用的对象。

(4). 本地方法栈中JNI(Native方法)引用的对象。

局部变量中确实没有，但是Native方法中是不是有呢？我们根据堆栈分析，通过仔细分析，我们会查看到如下的Native方法引用的对象。

native方法引用对象

ByteArrayClassLoader引用

在这里我们大概可以做出推测了，FGC发生的时候，某一个线程刚好在创建新的Class的实例对象，刚好本地方法持有了所有的ByteArrayClassLoader对象，导致其无法被GC掉，最终Metaspace中的类元数据信息也无法被释放。

遗留问题：

为什么getDeclaredConstructor0这个Native Method会持有所有的Class对象，差不多有67009个？

咨询了下相关JVM方面的专家，内存堆栈打印的代码如下所示：

jvm源码

MAT中出现的堆栈信息是图中红框部分所打印，表示的是该线程引用的JNI局部变量，JNI局部变量通常是通过Native方法JNIHandles::make_XXX相关方法，通过直接分析java代码暂时没有发现相关的调用地方，寒泉子给的意见是修改JVM的源码，打印出调用的地方，由于涉及的代码太多，暂时还没有找到问题发生的根本原因。

问题修复

找到问题的根本原因后，解决方式可以是多种多样的，一种是进行类加载器的缓存，避免每次重复创建无用的ByteArrayClassLoader和加载过多的类信息。

附加知识

摘取自寒泉子的文章

MC & MU & CCSC & CCSU

MC表示Klass Metaspace以及NoKlass Metaspace两者总共committed的内存大小，单位是KB，虽然从上面的定义里我们看到了是capacity，但是实质上计算的时候并不是capacity，而是committed，这个是要注意的

MU这个无可厚非，说的就是Klass Metaspace以及NoKlass Metaspace两者已经使用了的内存大小

CCSC表示的是Klass Metaspace的已经被commit的内存大小，单位也是KB

CCSU表示Klass Metaspace的已经被使用的内存大小

M & CCS

M表示的是Klass Metaspace以及NoKlass Metaspace两者总共的使用率，其实可以根据上面的四个指标算出来，即(CCSU+MU)/(CCSC+MC)

CCS表示的是NoKlass Metaspace的使用率，也就是CCSU/CCSC算出来的

PS：所以我们有时候看到M的值达到了90%以上，其实这个并不一定说明metaspace用了很多了，因为内存是慢慢commit的，所以我们的分母是慢慢变大的，不过当我们committed到一定量的时候就不会再增长了

MCMN & MCMX & CCSMN & CCSMX

MCMN和CCSMN这两个值大家可以忽略，一直都是0

MCMX表示Klass Metaspace以及NoKlass Metaspace两者总共的reserved的内存大小，比如默认情况下Klass Metaspace是通过CompressedClassSpaceSize这个参数来reserved 1G的内存，NoKlass Metaspace默认reserved的内存大小是2* InitialBootClassLoaderMetaspaceSize

CCSMX表示Klass Metaspace reserved的内存大小

综上所述，其实看metaspace最主要的还是看MC，MU，CCSC，CCSU这几个具体的大小来判断metaspace到底用了多少更靠谱