原文地址YGC问题排查,又让我涨姿势了!
主要内容:
超时量突然大面积增加,1分钟内甚至达到了上千次接口超时。
收到告警后,我们第一时间查看了监控系统,立马发现了YoungGC耗时过长的异常。
通过下图可以看出:在上线之前,YGC基本几十毫秒内完成,而上线后YGC耗时明显变长,最长甚至达到了3秒多。
由于YGC期间程序会Stop The World,而我们上游系统设置的服务超时时间都在几百毫秒,因此推断:是因为YGC耗时过长引发了服务大面积超时。
我们立刻摘掉了一个节点,然后通过以下命令dump了堆内存文件用来保留现场。
jmap -dump:format=b,file=heap pid
最后对线上服务做了回滚处理,回滚后服务立马恢复了正常,接下来就是长达1天的问题排查和修复过程。
使用ps aux | grep "applicationName=adsearch"命令查看到堆内存为4G,新生代和老年代均为2G,新生代采用ParNew收集器。再通过命令 jmap -heap pid 查到:新生代的Eden区为1.6G,S0和S1区均为0.2G。
本次上线并未修改JVM相关的任何参数,同时我们服务的请求量基本和往常持平。因此猜测:此问题大概率和上线的代码相关。
检查代码
正常情况下,Survivor区的使用率一直维持在很低的水平(大概30M左右),但是上线后,Survivor区的使用率开始波动,最多的时候快占满0.2G了。而且,YGC耗时和Survivor区的使用率基本成正相关。因此,我们推测:应该是长生命周期的对象越来越多,导致标注和复制过程的耗时增加。
我们进一步将怀疑对象锁定在:程序的全局变量或者类静态变量上。但是diff了本次上线的代码,我们并未发现代码中有引入此类变量。
对dump的堆内存文件进行分析
使用MAT工具导入了第1步dump出来的堆文件后,然后通过Dominator Tree视图查看到了当前堆中的所有大对象
对于YGC问题,原因集中在这两类上:
1、对存活对象标注时间过长:比如重载了Object类的Finalize方法,导致标注Final Reference耗时过长;或者String.intern方法使用不当,导致YGC扫描StringTable时间过长。
2、长周期对象积累过多:比如本地缓存使用不当,积累了太多存活对象;或者锁竞争严重导致线程阻塞,局部变量的生命周期变长。
针对第1类问题,可以通过以下参数显示GC处理Reference的耗时-XX:+PrintReferenceGC。添加此参数后,可以看到不同类型的 reference 处理耗时都很短,因此又排除了此项因素。
再回到长周期对象进行分析,重新从MAT堆内存中找到了第二个怀疑点。
大对象中排在第3位的ConfigService类进入了我们的视野,该类的一个ArrayList变量中竟然包含了270W个对象,而且大部分都是相同的元素。
ConfigService这个类在第三方Apollo的包中,不过源代码被公司架构部进行了二次改造,通过代码可以看出:问题出在了第11行,每次调用getConfig方法时都会往List中添加元素,并且未做去重处理。
我们的广告服务在apollo中存储了大量的广告策略配置,而且大部分请求都会调用ConfigService的getConfig方法来获取配置,因此会不断地往静态变量namespaces中添加新对象,从而引发此问题。
解决方案
为了快速验证YGC耗时过长是因为此问题导致的,我们在一台服务器上直接用旧版本的apollo client 包进行了替换,然后重启了服务,观察了将近20分钟,YGC恢复正常。
最后,我们通知架构部修复BUG,重新发布了super-pom,彻底解决了这个问题。