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日志中反应了好几个问题点?

  1. FGC时显示Metaspace的空间差不多又1.2G,[Metaspace: 297366K->297366K(1284096K)]?明显我们的最大只有512M
  2. 就算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 <pid>命令来查看类的加载和卸载情况,也可以设置 -verbose:gc参数来查看具体的类加载信息。

那具体是用到了哪些类加载器呢?有多种方式可以查看,一种最简单的就是通过jmap -hiso:live <pid>来查看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到底用了多少更靠谱

推荐阅读更多精彩内容