线上RPC超时故障排查及后续GC调优思路

本文记录了一次线上RPC服务调用超时问题的排查流程，排查过程中涉及到 JVM 优化的过程与思路，包括 JVM GC 原理以及问题排查思路，分享出来希望对大家有所帮助。

本文概要

• RPC服务异常和排查过程
• 排查方向
• 问题根因和解决方案
• JVM GC 原理与优化方案
• 基础排查工具使用

问题背景

RPC 服务调用方反馈服务有时会有超时。

查看监控平台发现有客户端调用超时，调用方的超时时间设置为 1s。

 

追根溯源

猜测1：JVM GC 时业务线程停顿，导致客户端超时。

遂查看节点的内存使用率，发现在有大量超时异常时，服务节点的内存使用率并没有明显的变化。此时觉得应该不是 GC 导致的问题。（埋下大坑）

 

猜测2：RPC服务 请求处理线程太少，大量请求在队列等待处理，导致客户端超时。

查看 RPC 服务配置的线程为 128。

 

查看服务排队总量最大为 31，最大值为 2 ，且大量超时发生时没有排队的请求量。

 

此时基本断定不是请求排队导致客户端超时。

猜测3：批量调用接口时，所有请求都没用命中缓存，导致客户端超时。

服务处理请求时，如果没有命中缓存会从 DB，Wtable（内部组件，类Redis），HTTP 获取原始数据，然后逐个设置缓存，方便下次使用。每次设置缓存的方式如下：

infos.forEach(info -> {
  cacheService.setCache(CacheKey.V1_DETAILINFO.getKey(), info, CacheExpire.HOUR_1.getTime());
});

获取了每个原始数据后，挨个设置缓存，过期时间统一为 1 小时。一小时后这些缓存同时过期，过期后的请求就会再次获取原始数据，导致请求响应时间变长。

优化如下：

infos.forEach(info -> {
  cacheService.setCache(CacheKey.DETAILINFO.getKey(), info, CacheExpire.HOUR_1.getTime() + random.nextInt(300));
});

同一批设置缓存的过期时间有一个随机数误差，让这一批缓存数据不至于同时过期，部分缓存过期后的请求时间相比全部缓存过期就会变短。分散同时获取原始数据的数量，降低延迟。

这一优化上线后，查看监控确实有效果，客户端超时数量锐减。此时，眉头舒展，觉得问题已经解决。

 

好景不长，没过两天，调用方同学反馈又有超时。

猜测4：数据库连接池不够用，需要 DB 操作时等待连接，导致客户端超时。

通过 trace 平台查看请求的调用链：

 

发现在一个请求调用链中有出现大量的 Wtable（内部组件，类Redis） 和 Redis 的 get 或者 set 操作，有的高达上百个。按每个 wtable、redis 的操作 1ms 算，那加起来也有上百毫秒。查看代码发现部分接口在循环里获取、设置缓存。但是这种情况不至于导致接口超时，所以没有立即着手优化。（尽量不要为了方便，在循环里有任何 IO 操作，最好批量 IO）

 

在有些慢请求中发现 MySQL 操作占用了时间线的绝大部分，怀疑可能有慢查询。但是查看数据库平台发现超时时刻并没有慢查询。

 

这时大胆怀疑起了 MySQL 的连接池不够（连接池最大连接数设置为 30），有需要操作 DB 时等待获取连接，导致 trace 统计 MySQL 操作时间长但是又没有慢查询的问题。很河狸。

为了方便观察连接池的状态，在服务增加了连接池监控，包含连接数量，活跃数量，空闲数量以及等待连接的数量，监控内容如下图所示：

 

 

查看连接池监控，在有客户端超时时，总的连接数量最高为 14，并没有超过设定的 30，等待获取连接的也基本没有，说明我们猜测连接池不够导致超时的设想也不成立。

一顿操作猛如虎，一看战绩零杠五，心态已经爆炸。

水落石出

没有其他排查方向，重新怀疑最先排除的 GC 问题。

服务节点的配置是 8C16G，服务使用的垃圾收集器为 CMS，堆内存为 12G。

因为没有输出 GC 日志，只能通过 jstat 简单查看 GC 情况，准备修改 JVM 参数，输出详细 GC 日志时，在监控平台发现了详细的 JVM 监控：

 

 

在 11 点钟 FGC 的时间接近 4s，老年代使用率从 80% 降到 20% 多。堆内存为 12G，新生代配置 4G，老年代为 8G，意味着回收近 4.8G 老年代内存耗时 4s。此时这个节点有客户端超时的情况。

为什么 FGC 的时间会突然这么长？五月下旬发现容器的内存有 16G 但堆内存只配了 8G，所以将堆内存调整为 12G。从历史监控数据可以看到调整之前每天一次 FGC 的频率，变成每 1.7 天一次，FGC 的时间 1s 增加到 3s。

因为堆内存较大，CMS 比较适合小内存的 JVM，大内存时在 FGC 需要回收较多对象时会造成长时间停顿。

目前在小内存应用上 CMS 的表现大概率仍然要会优于 G1，而在大内存应用上 G1 则大多能发挥其优势，这个优劣势的 Java 堆容量平衡点通常在 6GB 至 8GB 之间，当然，以上这些也仅是经验之谈，不同应用需要量体裁衣地实际测试才能得出最合适的结论，随着 HotSpot 的开发者对 G1 的不断优化，也会让对比结果继续向 G1 倾斜。《深入理解Java虚拟机》

所以没有优化 CMS FGC 的耗时直接将垃圾收集器调整为 G1，并输出 GC 日志：

-Xms12g 
-Xmx12g 
-Xss1024K 
-XX:MetaspaceSize=128m 
-XX:MaxMetaspaceSize=256m 
-XX:+UseG1GC 
-XX:MaxGCPauseMillis=200
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/opt/logs/server.hprof 
-XlogGC:/opt/logs/GC-server.log 
-verbose:GC 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails