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到底用了多少更靠谱
最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 206,968评论 6赞 482
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 88,601评论 2赞 382
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 153,220评论 0赞 344
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 55,416评论 1赞 279
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 64,425评论 5赞 374
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,144评论 1赞 285
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,432评论 3赞 401
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,088评论 0赞 261
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 43,586评论 1赞 300
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,028评论 2赞 325
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,137评论 1赞 334
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,783评论 4赞 324
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,343评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,333评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,559评论 1赞 262
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,595评论 2赞 355
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,901评论 2赞 345

推荐阅读更多精彩内容