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

2022-11-29 00:00:00 线程 时间 内存 耗时 流量

1现象

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

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

2问题排查

一般的，排查接口耗时，基本都习惯从外部流量，和各内部接口、逻辑块耗时，底层存储耗时等接口层面来观察。如果能在接口层面就找到了瓶颈，是理想的情况。否则，就要从JVM层面来排查，比如线程运行异常、GC异常等，势必要耗费更多的精力了。

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

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

  • 服务器差异？云服务器相较物理机，性能还是有很大差距，然而，摘掉报警机器后，报警又出现在了其他机器，那应该不是服务器的问题了。
  • 单机承载的流量不均衡？RPC路由策略默认加权轮询，但是在不设置权重属性的情况下，权重一样就蜕变成普通轮询。而且，看单机QPS，也基本一致，因此，这个原因也排除了。

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

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

Future异步调用

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

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

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

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

2.3 是不是代码出了性能bug

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

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

YGC耗时异常场景汇总：

  • GCRoot对象的扫描和标记时间异常
  • 存活对象的copy次数过多导致的耗时
  • 等待各线程到达安全点的时间过长
  • GC日志IO阻塞导致GC总耗时过长
  • 存在swap行为

FGC耗时异常场景汇总

  • 对象过早进入老年代
  • 元空间不足、分配担保等场景
  • 内存泄漏

诸多猜想

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

  • 有没有可能是参数设置不合理，在大流量下无法更好的适配服务；
  • 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%，期望大停顿时间40ms，禁用偏向锁。单看参数本身，可以发现一些问题：

  • 几个时间占比参数都要比默认值要大一些，主要是出于内存较大需要充分回收和更新缓存的同时要保证整体服务响应时间的考虑，比如GCTimeRatio和G1RSetUpdatingPauseTimePercent 。从合理性和历史运行数据来看，问题不大。
  • 并行线程数设置的有点大了，按JVM的官方建议，如果CPU<=8 ，则设置为cpu数，否则设置为8+((16-8)*5)/8 。这里和上面的FGC时间real时间么有小很多的现象大概率是对上了。
  • 没有设置年轻代的大小。那会不会是年轻代太小了，导致对象快速晋升呢

尝试调整参数

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

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

如上，主要增加了年轻代大小设置，减小了并行线程数。为的是让Young区尽量大，存放更多代的存活对象。然而，表现更差了，youngGC时间不受控，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的大小内存也不行，要不是扫描的数据只有几百M，要么是直接卡死。

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

Dump文件分析

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

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

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

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

3总结

因为配错了配置，触发了代码的隐藏BUG，造成了大量的配置项被重复多次添加到了静态变量，导致内存分配不足，触发FGC，导致服务耗时；流量大时，命中规则的次数大，导致内存增长快，流量小时，内存增长慢，这也就解释了为啥总是上午高峰期报，不过也给问题排查带来了不便，需要抓住上午的短暂异常时间来保存现场(关乎收入的服务，有问题得马上恢复)。也是因为规则的原因，命中的不那么多，不然可能早就OOM了，那样的话，可能就直接DUMP内存，不会这样来回来去的猜了。

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

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

相关文章