在高并发下,Java程序的GC问题属于很典型的一类问题,带来的影响往往会被进一步放大。不管是「GC频率过快」还是「GC耗时太长」,由于GC期间都存在Stop The World问题,因此很容易导致服务超时,引发性能问题。
我们团队负责的广告系统承接了比较大的C端流量,平峰期间的请求量基本达到了上千QPS,过去也遇到了很多次GC相关的线上问题。
这篇文章,我再分享一个更棘手的Young GC耗时过长的线上案例,同时会整理下YGC相关的知识点,希望让你有所收获。内容分成以下2个部分:
- 从一次YGC耗时过长的案例说起
- YGC的相关知识点总结
从一次YGC耗时过长的案例说起
今年4月份,我们的广告服务在新版本上线后,收到了大量的服务超时告警,通过下面的监控图可以看到:超时量突然大面积增加,1分钟内甚至达到了上千次接口超时。下面详细介绍下该问题的排查过程。
检查监控
收到告警后,我们第一时间查看了监控系统,立马发现了YoungGC耗时过长的异常。我们的程序大概在21点50左右上线,通过下图可以看出:在上线之前,YGC基本几十毫秒内完成,而上线后YGC耗时明显变长,最长甚至达到了3秒多。
由于YGC期间程序会Stop The World,而我们上游系统设置的服务超时时间都在几百毫秒,因此推断:是因为YGC耗时过长引发了服务大面积超时。
按照GC问题的常规排查流程,我们立刻摘掉了一个节点,然后通过以下命令dump了堆内存文件用来保留现场。
jmap -dump:format=b,file=heap pid
最后对线上服务做了回滚处理,回滚后服务立马恢复了正常,接下来就是长达1天的问题排查和修复过程。
确认JVM配置
用下面的命令,我们再次检查了JVM的参数
ps aux | grep "applicationName=adsearch"
-Xms4g -Xmx4g -Xmn2g -Xss1024K
-XX:ParallelGCThreads=5
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:+UseCMSCompactAtFullCollection
-XX:CMSInitiatingOccupancyFraction=80
可以看到堆内存为4G,新生代和老年代均为2G,新生代采用ParNew收集器。
再通过命令 jmap -heap pid 查到:新生代的Eden区为1.6G,S0和S1区均为0.2G。
本次上线并未修改JVM相关的任何参数,同时我们服务的请求量基本和往常持平。因此猜测:此问题大概率和上线的代码相关。
检查代码
再回到YGC的原理来思考这个问题,一次YGC的过程主要包括以下两个步骤:
1、从GC Root扫描对象,对存活对象进行标注
2、将存活对象复制到S1区或者晋升到Old区
根据下面的监控图可以看出:正常情况下,Survivor区的使用率一直维持在很低的水平(大概30M左右),但是上线后,Survivor区的使用率开始波动,最多的时候快占满0.2G了。而且,YGC耗时和Survivor区的使用率基本成正相关。因此,我们推测:应该是长生命周期的对象越来越多,导