记一次拐弯阁僚的接口耗时异常排查过程

1 现象

某后端系统，处于整个调用链路偏后的位置，对接口性能有着比较严格的要求。因此对外承诺的三个 9 响应时间为 200 多毫秒。

然而，从某天开始一到上午流量高峰，服务耗时就报警。随机从集群内的某些机器上报了出来，过了流量高峰就好很多……

2 问题排查

一般排查接口耗时，基本都习惯从外部流量、相关内部接口、逻辑块耗时、底层存储耗时等接口层面来观察。

如果能在接口层面就找到了瓶颈是最理想的情况，否则就要从 JVM 层面来排查。比如线程运行异常、GC 异常等，势必要耗费更多精力了。

2.1 服务器性能、流量分配等外在因素

虽然这类问题发生的概率比较小，但是看到几十台机器中只有几台在报。感觉还是有必要排查一下。

服务器差异？ 云服务器相较物理机，性能还是有很大差距。然而，摘掉报警机器后，报警又出现在了其他机器，那应该不是服务器的问题了；

单机承载的流量不均衡？ RPC 路由策略默认加权轮询，但是在不设置权重属性的情况下，权重一样就蜕变成普通轮询。而且，看单机 QPS 也基本一致。因此，这个原因也排除了。

2.2 是不是有业务重逻辑导致耗时增加

交互框架本身的限制

大型服务调用，基本都采用异步响应式调用方式，相比同步调用可以更好的利用资源。然而，异步响应式调用虽然节省了等待资源，但是也需要分出响应资源进行结果接收和返回。这里如果线程资源设置不合理，很有可能造成响应式阻塞。

Future异步调用

然而，服务响应资源还算充足，没有发现拒绝，排队等异常日志，排除。

业务逻辑本身的耗时

做业务开发的兄弟应该都有感触，有的业务逻辑那是真的复杂。如果其中还涉及外部调用，那绝对是妥妥的耗时大户。流量小的时候还好，随着流量范围的扩大，影响就会凸显出来了。

好巧，正好有一个业务刚做了运营动作。于是我们梳理了该业务场景涉及的执行链路。发现某个排序操作非常耗时，赶紧分析优化并上线。

我们以为发现了事情的真相，然而并无卵用。报警短信第二天又按时上班了。

2.3 是不是代码出了性能 Bug

既然不是流量问题，那就要从服务本身来看了。

在 JVM 层面，可能造成服务耗时增加的最大可能：一是异常 GC，二是线程资源阻塞或竞争。比较容易的应该是 GC 问题，因为有现成的日志和监控数据可循，优先怀疑 GC 的原因。

先来整理一下有哪些方面可能导致 GC：

YGC （Young GC）耗时异常场景汇总

GCRoot 对象的扫描和标记时间异常；

存活对象的 copy 次数过多导致的耗时；

等待各线程到达安全点的时间过长；

GC 日志的 IO 阻塞，导致 GC 总耗时过长；

存在 swap 行为。

FGC （Full GC）耗时异常场景汇总

对象过早进入老年代；

元空间不足、分配担保等场景；

内存泄漏。

诸多猜想

从上述罗列的可能性，其实会有很多猜想：

有没有可能是参数设置不合理，在大流量下无法更好的适配服务？

FGC 是因为老年代没有空闲空间。会不会是年轻代大小设置不合理，导致对象提前晋升？

如果年轻代空间充足，又是什么原因造成老年代占比快速上升？是有泄漏么？

2.4 问题分析

系统 JVM 监控异常

内存占用达到 80%、甚至 90% 或更高，直观感觉有点多了。但是拉长时间看，平时也是 70% 多。想到业务本身有很多的缓存项，如城市、商圈、地域类目等等，内容占用多也就暂时忽略了；

在接口异常的时间点常伴随 FGC 的发生。

日常的内存占用
GC 日志分析

2022-01-06T11:12:46.035+0800: 52873.818: [Full GC (Allocation Failure)  4511M->4419M(10G), 11.3422935 secs]   [Eden: 8192.0K(4496.0M)->0.0B(4624.0M) Survivors: 64.0M->0.0B Heap: 4511.4M(10.0G)->4419.4M(10.0G)], [Metaspace: 308300K->308289K(1310720K)] [Times: user=14.09 sys=0.00, real=11.34 secs]2022-01-06T11:12:57.378+0800: 52885.160: [Full GC (Allocation Failure)  4419M->4419M(10G), 11.3581878 secs]   [Eden: 0.0B(4624.0M)->0.0B(4624.0M) Survivors: 0.0B->0.0B Heap: 4419.4M(10.0G)->4419.4M(10.0G)], [Metaspace: 308289K->308237K(1310720K)] [Times: user=14.17 sys=0.00, real=11.36 secs]

看日志，只能看到现象是发生了连续两次 FGC。

第一次堆内存有减少，第二次几乎没有什么效果；另外，看 user 和 real 时间稍有点问题。按理说，FGC 也是多线程并行的，real 时间应该要小一些，但现在并非如此。

JVM 参数分析

当时的 VM 参数如下：

-XX:+UseG1GC -Xmx10g -Xms10g -XX:ParallelGCThreads=16 -XX:ConcGCThreads=8 -XX:GCTimeRatio=39 -XX:G1HeapRegionSize=8m -XX:MetaspaceSize=512M -XX:MaxMetaspaceSize=1024M -XX:MaxGCPauseMillis=40 -XX:G1RSetUpdatingPauseTimePercent=40 -XX:MaxTenuringThreshold=15 -XX:InitiatingHeapOccupancyPercent=70 -XX:-UseBiasedLocking

16 核 16G 的机器规格，设置了 10G 的堆大小、16 个并行 GC 线程、8 个并发线程。GC 耗时占比 2.5%，期望最大停顿时间 40 毫秒，禁用偏向锁。单看参数本身，可以发现一些问题：

几个时间占比参数都要比默认值要大一些，主要是出于内存较大需要充分回收和更新缓存的同时要保证整体服务响应时间的考虑，比如 GCTimeRatio 和 G1RSetUpdatingPauseTimePercent 。从合理性和历史运行数据来看，问题不大；

并行线程数设置得有点大了。按 JVM 的官方建议，如果 CPU<=8 ，则设置为 CPU 数，否则设置为 8 + ((16 - 8) * 5) / 8 。这里和上面的 FGC 时间相比 real 时间没有小很多的现象大概率是对上了；

没有设置年轻代的大小。那会不会是年轻代太小了，导致对象快速晋升呢？

尝试调整参数

啥也别说了。反正报了好几天了，先调调参数看下：

-XX:+UseG1GC -Xmx10g -Xms10g -Xmn6g-XX:ParallelGCThreads=10

如上，主要增加了年轻代大小设置，减小了并行线程数。为的是让 Young 区尽量大，存放更多的存活对象。

然而，结果表现更差了。YGC 时间不受控，FGC 也没减少，耗时倒是稍微好一点。

为啥呢？

主要是因为 G1 的 GC 时间预估功能，会动态的调整 Young 区的大小。现在 Young 区固定，导致了 GC 耗时控制失效。

所以，原因应该不是新生对象的快速晋升导致的了。

其他可能性分析

回看 JVM 监控，发现老年代有很大一部分根本 GC 不掉。

老年代内存监控

再看发生问题时的 GC 日志，发现之前的 GC 日志查看有所遗漏：

2022-01-06T11:12:46.004+0800: 52873.787: [GC concurrent-root-region-scan-start]2022-01-06T11:12:46.007+0800: 52873.790: [GC pause (G1 Humongous Allocation) (young)2022-01-06T11:12:46.017+0800: 52873.799: [GC concurrent-root-region-scan-end, 0.0121935 secs]2022-01-06T11:12:46.017+0800: 52873.799: [GC concurrent-mark-start], 0.0249766 secs]   [Root Region Scan Waiting: 9.6 ms]   [Parallel Time: 13.6 ms, GC Workers: 10]   ...

看到了 G1 Humongous Allocation 是大对象分配。我们的 region 块设置的是 8M，感觉不小了，但还有大对象。

啥对象能占超过 8M 的内存呢？

查看内存占用大的对象

这个 Object 是什么鬼？

如果是基本数据类型占这么多我觉得还能理解，但 Object 占这么多就不太正常。杀手锏，来 dump 一下吧。

结果悲剧了。

10G 内存，发生异常时最多占比有 90% 多。本地 MAT 根本打不开，就算修改了 MAT 的最大最小内存也不行。要不是扫描的数据只有几百兆，要么是直接卡死。

没办法，只能单独申请了一台超大内存的 Linux 服务器。安装 MAT 进行处理，然后再将结果文件导出到本地用浏览器分析。

Dump 文件分析

Are you joking me ? 谁能帮数下，这是多少个对象。

问题很显然了，内存泄漏。剩下的就是找对应的操作这个对象的代码了。

最后发现，原来是在代码中设置了静态集合存储业务规则。又因为配置问题，触发了代码隐藏的异常。流量每次命中该规则时，就会将全量名单再次添加一次到集合列表，导致列表一再扩容，直到内存达到阈值。

有同学可能会问，为啥没有 OOM 呢？嗯，问得好，你猜……

总结

因为配置错误触发了代码的隐藏 Bug，造成了大量的配置项被重复多次添加到了静态变量，导致内存分配不足。进而触发 FGC，导致服务耗时。

流量大的时候，命中规则的次数大，导致内存增长快；流量小的时候，内存增长慢。这也就解释了为啥总是上午高峰期报。不过也给问题排查带来了不便，需要抓住上午的短暂异常时间来保存现场（关乎收入的服务，有问题得马上恢复）。也是因为规则的原因，命中的不那么多，不然可能早就 OOM 了。那样的话，可能就直接 dump 内存，不会这样来回来去的猜了。

归根结底一句话，出现了突发的系统异常，去找近期的代码改动和配置改动。一般没跑。

另外，关于 ParallelGCThreads 的那个计算公式，个人猜测，由于 G1 为大内存场景设计，在 GC 时，会有诸多关联操作，如更新 RS 缓存、计算 region 价值得分、运行时间预估算法等等，8 个线程可能正好把这些任务分个差不多。因此，当少于 8 核时，每个核都要参与；而大于 8 核时，增加一些辅助线程来参与，但线程过多又有可能造成资源抢占、上下文切换等开销。

- EOF -

推荐阅读点击标题可跳转

1、一个不错的线上故障排查案例

2、一次压测引出的线上Full GC排查

3、JAVA 线上故障排查完整套路，从 CPU、磁盘、内存、网络、GC 一条龙！

看完本文有收获？请转发分享给更多人

关注「ImportNew」，提升Java技能