一次ygc越来越慢的问题排查过程
问题发现场景
某天突然收到线上应用的gc时间过长的告警,刚开始只有一台机器偶尔报一下,后续其他机器也纷纷告警,具体告警的阈值是应用10分钟内ygc的总时长达到了6.6s。
初步排除过程
- 按照gc问题常规排查流程,还是先保留现场,jmap -dump:format=b,file=temp.dump pid。
- 查看下gc日志,发现出问题的时候的单次ygc耗时几乎有200ms以上了。正常来说单次ygc在100ms以下,基本可以认为应用是比较健康的。所以这时候已经可以确定告警的原因就是ygc比较慢。
- jvisualvm打开刚刚dump的文件看下能不能发现什么东西,看了下,也看不出什么特殊的,因为本身dump的时候会触发一次full gc,dump下来的堆里面的内容只有1G左右(jvm参数堆内存配置的是4G)如下图,也没发现什么特殊的东西
。
- 然后看下ygc近期耗时的走势图,下图纵坐标每10分钟gc总耗时(单位:s),横坐标日期,可以看到在2月22号应用重启后gc总耗时降下来了,然后随着时间推移,gc变得越来越慢,并且这个变慢的过程非常缓慢,正常情况下重启一次到应用触发gc告警,需要1至2周才能出现。
。
进一步排查
- 网上搜了下有没有相关案例,相关资料也非常少,然后看到 了http://zhuanlan.51cto.com/art/201706/543485.htm 笨神的一篇文章,这篇文章简单总结起来就是使用jdk中的1.8的nashorn js引擎使用不当触发了底层JVM的一个缺陷。然后回到我这边来,发现和我这边的场景也挺类似的,应用也大量使用了nashorn 引擎来执行javascript脚本,所以我初步猜测也是nashorn引擎使用不当导致。
- 为了验证我以上的想法,找运维加了
-XX:+PrintReferenceGC
参数,经过一段时间观察,应用重启后,观察了一段时间,发现gc日志中JNI Weak Reference处理时长变得越来越长。而且占用整个ygc时长的大部分。 - 再回到刚刚dump的那张图里面,能看到实例数排在前面的也有nashorn引擎相关的内容,如下图,现在几乎可以断定问题出在的执行某个javascript脚本。
- 现在确认了出问题的大致方向。但是该应用执行的javascript脚本也有10多个,所以还没发直接定位到是哪个脚本导致的。所以接下来就是定位具体的脚本了。初步想法是直接根据上图的中的
jdk.nashorn.internal.ir.IdenNode
通过引用链找到可疑的js脚本对应的String
,尝试了很多次发现都失败了。主要本身对jdk.nashorn
包下类不是很熟悉,再加上引用链都比较长,所以找了很久都没有找到这个类和脚本的应用关系。 - 于是换了一种思路,内存中,脚本肯定会以
String
对象存在,String
底层采用char[]
来存储字符。所以直接找char[]
实例中内容为js脚本的,但是这里又遇到一个问题,看上面的dump文件图,会发现char[]
实例数当前内存有100w+,这里就抓住了部分js脚本长度比较长的一个特点。直接根据size正序排列,长度前10的字符串,就直接就找到了一个脚本,顺着引用链会轻易发现,js脚本的内容都是保存在Source$RawData
对象中的,如下图 - 然后回到VisualVM的
Classes
栏目,直接搜索Source$RawData
,可以看到有241个实例,如下图,这241个,然后找了出现频率比较高的几个js脚本,然后看了对应脚本的调用方式,发现其中一个脚本每次执行都是通过
ScriptEngine.eval
这种方式来执行,就造成了``JNIHandleBlock```,不断增长的问题,最终导致ygc时,处理JNI Weak Reference的时间越来越长。 - 如何解决:修改了这个脚本的调用方式。不用每次执行
eval
方法,换成Bindings的方式调用。 - 修改后,经过一周的观察。ygc时间以及区域稳定了,如下图
总结
- 小插曲:其实这个问题在18年10月份左右都出现了,早期也考虑彻底解决过,也探索了不少方法。比如下:
- 最开始的时候怀疑是G1 收集器的问题,直接把G1收集器改回CMS收集器,其中调整该参数的过程中也发生了一个小问题,具体如下。
- 从G1改到CMS改回来的参数设置堆空间大小相关的参数变成了
-Xms4000m -Xmx4000m -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 -Dio.netty.availableProcessors=4 -XX:ParallelGCThreads=4 -Dpinpoint.applicationName=crawler-worker.product-bank
这样,其中-Xms4000m
是初始化堆大小,-Xmx4000m
是最大堆大小,然后重启应用,重启后,就收到ygc频繁的告警,然后用jstat -gc pid 3000
看了下,发现了奇怪的地方(如下图)年轻代总容量才300多m(S0C+S1C+EC),而年老大总容量(OC)有3700多m,这种情况就直接导致了,直接分配对象空间的eden区域很容易就占满了,而直接触发ygc,而导致这个问题的原因呢,是忘记配置
-Xmn1024m
参数导致,这个参数就是制定年轻代的大小,这里的大小配置成整个堆的1/4至1/2都是合理的,加上这个参数后,刚启动应用就ygc时间过长的问题就得到了解决。
- 从G1改到CMS改回来的参数设置堆空间大小相关的参数变成了
- 后面发现也没什么效果,又怀疑是堆空间年轻代的空间设置小了。之前整个堆4000M,年轻代设置的1000M。后面把年轻代的空间调整至1200M,发现也没什么效果。在这个过程中,发现也没什么效果,再加上这个过程非常缓慢,重启一次应用也能撑个1至2周,所以也拖到了现在也就是19年2月底,算是彻底解决了这个问题。
- 最开始的时候怀疑是G1 收集器的问题,直接把G1收集器改回CMS收集器,其中调整该参数的过程中也发生了一个小问题,具体如下。
- 个人觉得ygc缓慢相关的问题不太好排查,相比full gc问题或者OOM的相关问题,本身ygc带给我们的东西不够多,并且dump下来的信息,也不是保证有用的,可能也是问题被掩盖后的一些无关信息。
- 在排查gc相关问题,个人觉得需要对整个jvm堆内存的划分,以及gc的一系列流程,有所了解和掌握,才能够快速的定位和排查问题。
参考文章
版权声明 作者:wycm
出处:https://my.oschina.net/wycm/blog/3023965
您的支持是对博主最大的鼓励,感谢您的认真阅读。
本文版权归作者所有,欢迎转载,但未经作者同意必须保留此段声明,且在文章页面明显位置给出原文连接,否则保留追究法律责任的权利。

低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。
持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。
转载内容版权归作者及来源网站所有,本站原创内容转载请注明来源。
- 上一篇
第1届全球学生开源年会 sosconf 将于 2019年8月在美国南加州大学举行
学生开源年会:Students Open Source Conference(简称 sosconf),是首个由学生组织、面向学生的非盈利全球性开源技术峰会。sosconf 2019 将于 8 月下旬在美国南加州大学举行。 2019年3月18日讯,美国洛杉矶 学生开源年会组委会今天正式宣布,第1届全球学生开源年会 sosconf 2019 将于今年8月在美国南加州大学举行,这是继去年第0届学生开源年会成功召开后,该会议第一次在美国举办。 学生开源年会(sosconf )是首个由学生组织面向学生的非盈利社区全球性开源技术峰会,峰会基于开放源代码的理念,鼓励学生享受开源、了解开源、参与开源、贡献开源,并能从开源中得到实践和乐趣。峰会每年在不同国家不同城市举办,从演讲者、组织者、志愿者到听众,绝大多数为在校学生,包括中学生、大学生硕士研究生和博士研究生,其中演讲者和志愿者仅限学生身份报名,听众不做任何限制。 南加州大学(University of Southern California ),简称南加大,位于加州洛杉矶市中心,由监理会于1880年创立,是加州最古老的私立研究型大学,亦是全球顶尖的...
- 下一篇
在浏览器中进行深度学习:TensorFlow.js (九)训练词向量 Word Embedding
词向量,英文名叫Word Embedding,在自然语言处理中,用于抽取语言模型中的特征,简单来说,就是把单词用一个向量来表示。最著名的Word Embedding模型应该是托马斯·米科洛夫(Tomas Mikolov)在Google带领的研究团队创造的Word2vec。 词向量的训练原理就是为了构建一个语言模型,我们假定一个词的出现概率是由它的上下问来决定的,那么我们找来很多的语素来训练这个模型,也就是通过上下文来预测某个词语出现的概率。 如上图所示,词嵌入向量的训练主要有两种模式: 连续词袋 CBOW, 在这个方法中,我们用出现在该单词的上下文的词来预测该单词出现的概率,如上图就是该单词的前两个和后两个。然后我们可以扫描全部的训练语素(所有的句子),对于每一次出现的词都找到对于的上下文的4个词,这样我们就可以构建一个训练集合来训练词向量了。 Skip-Gram和CBOW正好相反,它是用该单词来预测前后的4个上下文的单词。注意这里和上面的4个都是例子,你可以选择上下文的长度。 那么训练出来的词向量它的含义是什么呢? 词向量是该单词映射到一个n维空间的表示,首先,所有的单词只有在表示为...
相关文章
文章评论
共有0条评论来说两句吧...
文章二维码
点击排行
推荐阅读
最新文章
- SpringBoot2全家桶,快速入门学习开发网站教程
- Eclipse初始化配置,告别卡顿、闪退、编译时间过长
- Jdk安装(Linux,MacOS,Windows),包含三大操作系统的最全安装
- CentOS7编译安装Gcc9.2.0,解决mysql等软件编译问题
- MySQL8.0.19开启GTID主从同步CentOS8
- CentOS7,CentOS8安装Elasticsearch6.8.6
- 2048小游戏-低调大师作品
- CentOS8,CentOS7,CentOS6编译安装Redis5.0.7
- Windows10,CentOS7,CentOS8安装Nodejs环境
- CentOS7安装Docker,走上虚拟化容器引擎之路