记一次生产环境接口返回时长异常排查

type

Post

status

Published

date

Sep 17, 2023

slug

summary

背景

周六晚上22：30 左右被叫醒，用户说 APP 的信息列表界面异常卡顿，别的界面没有出现这样问题。

在第一次排查的时候发现这个持续卡顿的时长很短，直至23：00就突然恢复正常，其中发现相关服务的机器 CPU 使用率达到 200~300%，内存使用 4.4GB，查询接口返回时常为 5~20s 及其不稳定，查询接口是一个批量查询的操作，没有做分页，返回数据大小为 1MB 左右。

这个服务部署了三台机器，其中两台机器（也可能是 nginx 均衡负载配置问题）CPU和内存使用率异常的高。

之后观察周日到周五从未复现这个问题，但是周六晚上22：40 左右又开始出现这个问题，说明周六晚上是服务高峰期，时间依旧很短，没有足够时间准备排查，监控系统也不完善，但是目前已经大概知道复现的时间，只要提前蹲点就足够时间排查。

解决

通过 top命令知道是具体那个 Java 进程异常了，接下来就继续细分到具体那些线程，通过 Jstack可以得到的线程快照，以及 top -H pid 可以得到那些线程占用资源比较高的线程，发现占用 CPU 资源比较多的线程是 GC 线程。

然后使用 Jinfo pid 查看 JVM 一些配置参数，得知内存被限制至 4GB，但是已经使用 4.4GB 竟然也没有溢出，仅仅是 CPU 使用率上涨，接着去看了 GCLog 发现 YGC 一分钟70至80次和 Full GC 五至十分钟执行一次，内存是有问题，但是持续到结束也没有内存异常说明也是可以回收内存，只不过是回收完毕又很快就填满了。

通过 jmap可以看到堆那部分内存被那些对象占用以及堆的一些使用率，新生代的 Eden区内存直至 99.3% 几乎完全使用完，接着我把刷新频率为 100ms 可以观察到差不多 100~300ms 就把 Eden 内存吃满。结合之前的查询接口来看确实是正常，因为批量生成新对象，又快速回收，所以不会导致内存溢出，但是回收频率比较高。对于这块业务之前不是我负责代码肯定不敢乱动（即使最后评估了设计不合理），但又需要解决这个问题，在之前得知内存被限制 4GB 实际机器内存有 16GB 是足够内存分配，并且大多数对象都是在 Eden 销毁了，所以根据上面尝试加大内存和把 Eden 大小调整试试是否能把 GC 频率降低，调整之后确实降到一分钟 20 至 30 次左右，CPU 也降下来，然后坐等到下周周六 22 点。

观察到现在已经是恢复正常的第二周，接口到返回时长为 130~200ms （除了偶尔网络浮动）。

最后

当时一边排查一边跟群友分享，有推荐使用 EasyGC 分析日志，GC 频率很高，但是给出报告说一切正常。又有人推荐把内存快照搞下来慢慢分析，使用工具分析有两种模式，一种是执行完整 GC 之后的保留对象，一种是不执行 GC。执行完整 GC 发现其实就剩余 200MB 对象，说明大多数对象都可以正常回收只不过是对象生成频繁，然后又看具体那些对象占用内存多，发现是 String 使用比较多以及业务的某个对象（其实这个对象就包含很多 String的引用），接下来如果仅仅加内存不够的话需要把这部分重新设计了。