一次ygc愈来愈慢的问题排查过程

问题发现场景

某天忽然收到线上应用的gc时间过长的告警，刚开始只有一台机器偶尔报一下，后续其余机器也纷纷告警，具体告警的阈值是应用10分钟内ygc的总时长达到了6.6s。

初步排除过程

1. 按照gc问题常规排查流程，仍是先保留现场，jmap -dump:format=b,file=temp.dump pid。
2. 查看下gc日志，发现出问题的时候的单次ygc耗时几乎有200ms以上了。正常来讲单次ygc在100ms如下，基本能够认为应用是比较健康的。因此这时候已经能够肯定告警的缘由就是ygc比较慢。
3. jvisualvm打开刚刚dump的文件看下能不能发现什么东西，看了下，也看不出什么特殊的，由于自己dump的时候会触发一次full gc，dump下来的堆里面的内容只有1G左右（jvm参数堆内存配置的是4G）以下图，也没发现什么特殊的东西。
4. 而后看下ygc近期耗时的走势图，下图纵坐标每10分钟gc总耗时(单位:s)，横坐标日期，能够看到在2月22号应用重启后gc总耗时降下来了，而后随着时间推移，gc变得愈来愈慢，而且这个变慢的过程很是缓慢，正常状况下重启一次到应用触发gc告警，须要1至2周才能出现。。

进一步排查

1. 网上搜了下有没有相关案例，相关资料也很是少，而后看到 了http://zhuanlan.51cto.com/art/201706/543485.htm 笨神的一篇文章，这篇文章简单总结起来就是使用jdk中的1.8的nashorn js引擎使用不当触发了底层JVM的一个缺陷。而后回到我这边来，发现和我这边的场景也挺相似的，应用也大量使用了nashorn 引擎来执行javascript脚本，因此我初步猜想也是nashorn引擎使用不当致使。
2. 为了验证我以上的想法，找运维加了-XX:+PrintReferenceGC参数，通过一段时间观察，应用重启后，观察了一段时间，发现gc日志中JNI Weak Reference处理时长变得愈来愈长。并且占用整个ygc时长的大部分。
3. 再回到刚刚dump的那张图里面，能看到实例数排在前面的也有nashorn引擎相关的内容，以下图，如今几乎能够判定问题出在的执行某个javascript脚本。
4. 如今确认了出问题的大体方向。可是该应用执行的javascript脚本也有10多个，因此还没发直接定位到是哪一个脚本致使的。因此接下来就是定位具体的脚本了。初步想法是直接根据上图的中的jdk.nashorn.internal.ir.IdenNode经过引用链找到可疑的js脚本对应的String，尝试了不少次发现都失败了。主要自己对jdk.nashorn包下类不是很熟悉，再加上引用链都比较长，因此找了好久都没有找到这个类和脚本的应用关系。
5. 因而换了一种思路，内存中，脚本确定会以String对象存在，String底层采用char[]来存储字符。因此直接找char[]实例中内容为js脚本的，可是这里又遇到一个问题，看上面的dump文件图，会发现char[]实例数当前内存有100w+，这里就抓住了部分js脚本长度比较长的一个特色。直接根据size正序排列，长度前10的字符串，就直接就找到了一个脚本，顺着引用链会轻易发现，js脚本的内容都是保存在Source$RawData对象中的，以下图
6. 而后回到VisualVM的Classes栏目，直接搜索Source$RawData，能够看到有241个实例，以下图，这241个，而后找了出现频率比较高的几个js脚本，而后看了对应脚本的调用方式，发现其中一个脚本每次执行都是经过ScriptEngine.eval这种方式来执行，就形成了``JNIHandleBlock```，不断增加的问题，最终致使ygc时，处理JNI Weak Reference的时间愈来愈长。
7. 如何解决：修改了这个脚本的调用方式。不用每次执行eval方法，换成Bindings的方式调用。
8. 修改后，通过一周的观察。ygc时间以及区域稳定了，以下图

总结

1. 小插曲：其实这个问题在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时间过长的问题就获得了解决。
   • 后面发现也没什么效果，又怀疑是堆空间年轻代的空间设置小了。以前整个堆4000M，年轻代设置的1000M。后面把年轻代的空间调整至1200M，发现也没什么效果。在这个过程当中，发现也没什么效果，再加上这个过程很是缓慢，重启一次应用也能撑个1至2周，因此也拖到了如今也就是19年2月底，算是完全解决了这个问题。
2. 我的以为ygc缓慢相关的问题不太好排查，相比full gc问题或者OOM的相关问题，自己ygc带给咱们的东西不够多，而且dump下来的信息，也不是保证有用的，可能也是问题被掩盖后的一些无关信息。
3. 在排查gc相关问题，我的以为须要对整个jvm堆内存的划分，以及gc的一系列流程，有所了解和掌握，才可以快速的定位和排查问题。

参考文章

• http://zhuanlan.51cto.com/art/201706/543485.htm

版权声明
做者：wycm
出处：http://www.javashuo.com/article/p-xgahnile-cn.html
您的支持是对博主最大的鼓励，感谢您的认真阅读。
本文版权归做者全部，欢迎转载，但未经做者赞成必须保留此段声明，且在文章页面明显位置给出原文链接，不然保留追究法律责任的权利。