一次诡异的线上GC耗时过长问题排查

一天晚上，突然收到了线上部分服务耗时过长和配置中心模块的某台服务器FullGC耗时报警。大伙纷纷登录线上服务器，排查时通过GC日志发现配置中心模块确实有FullGC耗时过长的情况，每次FullGC时间长达5s以上，有的甚至长达十几秒，导致期间配置中心应答全部超时。

配置中心服务一直很稳定，给线上服务提供稳定高效的配置数据查询，最近也没有大功能发布，咋会突然出现FullGC问题？

经过老司机排查，发现该台服务器配置中心耗时高FullGC是有规律的出现的，大约每五天会出现一次，其他时间FullGC是正常的，然后这个周期会以十分缓慢的速度缩小。由于周期过长，给问题定位带来了困难，因为无法立即重现当时的场景。

有的老司机决定从代码层面去找原因、有的老司机去看配置中心的其他服务器有没有相同的问题，总结如下：

1. 排查了代码，发现出问题的只有可能是jackson库等第三方库，因为配置中心的业务逻辑并不复杂。

2.dump了出问题的服务器的配置中心内存（因为无法再出问题的时刻dump，所以只能退而求其次在正常的时候进行dump），没发现内存泄露的地方。

3. 每台服务器都是混合部署多个Java服务，配置中心集群部署了3台，另外两台的配置中心也有FullGC过长的问题，但频率比出问题的这台低。

4.排查发现出现GC耗时过长的服务器还部署着大数据的某个高IO类型的应用，但奇怪的是出问题的时刻，配置中心的服务器的cpu、io都正常，只是内存使用的比较多。

排查了几个小时毫无头绪，只能回过头来再仔细看GC日志，看是否能发现一些其他细节:

后面查看GC日志发现Rescan阶段weak refs processing的超时都超长，GC日志里大量可见[weak refs processing, 4.0028880 secs]，排查的方向就逐渐转向了weak refs processing 为什么会花费如此长的时间？没人知道。

难过了几天后。。。

我找到了一个可视化的GC分析工具gceasy.io，分析后发现一个之前一直忽略的现象，GC真实的耗时是远大于用户耗时和系统耗时的：

[Times: user=2.10 sys=0.43, real=8.28 secs]

。我们知道JVM本身作为一个进程也是由Linux系统进行内存分配，而Linux的内存空间由两部分构成，物理内存和Swap空间，假如GC时有一部分内容被交换到Swap，遍历到这部分的时候就需要将其交换回内存，极端情况下甚至会把整个堆分区轮流往Swap写一遍，而磁盘交换的速度是远慢于物理内存的，如果GC和Swap同时发生会导致超长时间的卡顿，通过sar -W -f命令分析发现Swap时间完全吻合发生耗时超长的GC时间:

于是，基本可以断定是系统的物理内存不够用导致系统发生Swap，最终导致耗时超长的GC发生，关闭Linux的Swap后引用的GC时间恢复到500ms以下。

虽然GC耗时超长的问题得到了解决，但是仔细思考一下就会发现问题的解决完全依赖程序员的推理过程和知识储备，那么是不是可以有更简单更快速的问题排查定位手段，我认为答案是可以的，那就是更加智能化的监控，将业务指标，应用指标，系统指标打通关联，在FullGC超时报警的时候通知告知业务开发系统发生了Swap，并且能展示对业务量和GMV等指标的影响。好的基础设施就像强大的武器，虽然依赖好的枪法用手枪也能杀死敌人，但是手里有把AKM或M16还是更容易吃鸡。