YGC问题排查，又让我涨姿势了

末蓝、 2023-09-29 07:29 22阅读 0赞

![8f39a08b4957b3dca3dccee6cc4cc7b7.png][]

在高并发下，Java程序的GC问题属于很典型的一类问题，带来的影响往往会被进一步放大。不管是「GC频率过快」还是「GC耗时太长」，由于GC期间都存在Stop The World问题，因此很容易导致服务超时，引发性能问题。

我们团队负责的广告系统承接了比较大的C端流量，平峰期间的请求量基本达到了上千QPS，过去也遇到了很多次GC相关的线上问题。

这篇文章，我再分享一个更棘手的Young GC耗时过长的线上案例，同时会整理下YGC相关的知识点，希望让你有所收获。内容分成以下2个部分：

*  从一次YGC耗时过长的案例说起
 *  YGC的相关知识点总结

### 从一次YGC耗时过长的案例说起 ###

今年4月份，我们的广告服务在新版本上线后，收到了大量的服务超时告警，通过下面的监控图可以看到：超时量突然大面积增加，1分钟内甚至达到了上千次接口超时。下面详细介绍下该问题的排查过程。

![189c94e19c1d35d6dbb1d191795d19df.png][]

#### 检查监控 ####

收到告警后，我们第一时间查看了监控系统，立马发现了YoungGC耗时过长的异常。我们的程序大概在21点50左右上线，通过下图可以看出：在上线之前，YGC基本几十毫秒内完成，而上线后YGC耗时明显变长，最长甚至达到了3秒多。

![8b4737f6d7bd59bb734e678bd544fad6.png][]

由于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区的使用率基本成正相关。因此，我们推测：应该是长生命周期的对象越来越多，导

[8f39a08b4957b3dca3dccee6cc4cc7b7.png]: https://img-blog.csdnimg.cn/img_convert/8f39a08b4957b3dca3dccee6cc4cc7b7.png
[189c94e19c1d35d6dbb1d191795d19df.png]: https://img-blog.csdnimg.cn/img_convert/189c94e19c1d35d6dbb1d191795d19df.png
[8b4737f6d7bd59bb734e678bd544fad6.png]: https://img-blog.csdnimg.cn/img_convert/8b4737f6d7bd59bb734e678bd544fad6.png