GC 问题排查实战案例
这一部分,我们来看一个实际的案例。
假设我们有一个提供高并发请求的服务,系统使用 Spring Boot 框架,指标采集使用 MicroMeter,监控数据上报给 Datadog 服务。
当然,Micrometer支 持将数据上报给各种监控系统,例如:AppOptics、Atlas、Datadog、Dynatrace、Elastic、Ganglia、Graphite、Humio、Influx、Instana、JMX、KairosDB、New Relic、Prometh eus、SignalFx、Stackdriver、StatsD、Wavefront 等等。
有关MicroMeter的信息可参考:
问题现象描述
最近一段时间,通过监控指标发现,有一个服务节点的最大 GC 暂停时间经常会达到 400ms 以上。
如下图所示:
从图中可以看到,GC 暂停时间的峰值达到了 546ms,这里展示的时间点是 2020 年 02 月 04 日 09:20:00 左右。
客户表示这种情况必须解决,因为服务调用的超时时间为 1s,要求最大 GC 暂停时间不超过 200ms,平均暂停时间达到 100ms 以内,对客户的交易策略产生了极大的影响。
CPU 负载
CPU 的使用情况如下图所示:
从图中可以看到:系统负载为 4.92,CPU使用率 7% 左右,其实这个图中隐含了一些重要的线索,但我们此时并没有发现什么问题。
GC 内存使用情况
然后我们排查了这段时间的内存使用情况:
从图中可以看到,大约 09:25 左右 old_gen 使用量大幅下跌,确实是发生了 FullGC。
但 09:20 前后,老年代空间的使用量在缓慢上升,并没有下降,也就是说引发最大暂停时间的这个点并没有发生 FullGC。
当然,这些是事后复盘分析得出的结论。当时对监控所反馈的信息并不是特别信任,怀疑就是触发了 FullGC 导致的长时间 GC 暂停。
为什么有怀疑呢,因为 Datadog 这个监控系统,默认 10s 上报一次数据。有可能在这 10s 内发生些什么事情但是被漏报了(当然,这是不可能的,如果上报失败会在日志系统中打印相关的错误)。
再分析上面这个图,可以看到老年代对应的内存池是 "ps_old_gen",通过前面的学习,我们知道,ps 代表的是 ParallelGC 垃圾收集器。
JVM 启动参数
查看 JVM 的启动参数,发现是这样的:
-Xmx4g -Xms4g
我们使用的是 JDK 8,启动参数中没有指定 GC,确定这个服务使用了默认的并行垃圾收集器。
于是怀疑问题出在这款垃圾收集器上面,因为很多情况下 ParallelGC 为了最大的系统处理能力,即吞吐量,而牺牲掉了单次的暂停时间,导致暂停时间会比较长。
使用 G1 垃圾收集器
怎么办呢?准备换成 G1,毕竟现在新版本的 JDK 8 中 G1 很稳定,而且性能不错。
然后换成了下面的启动参数:
# 这个参数有问题,启动失败
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMills=50ms
结果启动失败,忙中出错,参数名和参数值都写错了。
修正如下:
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50
接着服务启动成功,等待健康检测自动切换为新的服务节点,继续查看指标。
看看暂停时间,每个节点的 GC 暂停时间都降下来了,基本上在 50ms 以内,比较符合我们的预期。
嗯!事情到此结束了?远远没有。
“彩蛋”惊喜
过了一段时间,我们发现了个下面这个惊喜(也许是惊吓),如下图所示:
中奖了,运行一段时间后,最大 GC 暂停时间达到了 1300ms。
情况似乎更恶劣了。
继续观察,发现不是个别现象:
内心是懵的,觉得可能是指标算错了,比如把 10s 内的暂停时间全部加到了一起。
注册 GC 事件监听
于是想了个办法,通过 JMX 注册 GC 事件监听,把相关的信息直接打印出来。
关键代码如下所示: