💢线上高延迟请求排查

前几天排查了一个业务接口执行高延迟的问题，也挺有参考意义的，分享一下排查过程。

现象是业务反馈有一个接口业务逻辑其实很简单，但是调用一次耗时，如下图所示：

排查应用运行状态

首先第一步需要查看当时的应用运行状态，包含当时的日志、JVM 的各种监控等。

因为我们接入了 OpenTelemetry，所以 trace 和日志是可以关联起来的。

点击链路系统旁边的日志按钮可以直接跳转。

可以通过 trace_id 查询到相关日志：

通过日志可以看出耗时大约在 4s 多一点，然后结合代码发现这两段日志分别是在进入一个核心业务方法之前和方法内打印的。

而第一行日志是在一个自定义限流器中打印的，这个限流器是使用 Guava 的 RateLimiter实现的。

我的第一反应是不是这个限流器当时限流了，从而导致阻塞了；但查看了当时的 QPS 发现完全低于限流器的配置，所以基本可以排除它的嫌疑了。

JVM 监控

之后我们查询当时的 JVM 监控发现当时的 GC 频繁，而堆内存也正好发生了一次回收，初步判断是 GC 导致的本次问题。

但为啥会导致频繁的 GC 呢，还需要继续排查。

内存排查

我们在应用诊断中集成了 Pyroscope的持续剖析，可以实时查看内存的占用情况。

通过内存分析发现有大量的 JSON 序列化占用了大量的内存，同时还发现 Pod 已经被重启好几次了：

查看原因发现是 Pod OOM 导致的。

因此非常有可能是 GC 导致的，恰好那段时间发生了 GC 内存也有明显变化。

最后再通过 arthas 确认了 GC 非常频繁，可以确认目前的资源是是非常紧张的，咨询业务之后得知该应用本身占用的资源就比较大，没有太多优化空间，所以最终决定还是加配置。


还是提高硬件效率最高，目前运行半个月之后 Pod 内存表现稳定，没有出现一次 OOM 的异常。

总结

虽然最后的处理的方式是简单粗暴的，但其中的过程还是有意义的，遇到不同的情况也有不同的处理方式。

比如在排查过程中发现内存消耗异常，通过内存分析发现代码可以优化，那就优化代码逻辑。

如果是堆内存占用不大，但是 Pod 还是 OOM 导致重启，那就要看看 JVM 的内存分配是否合理，应该多预留一些内存给堆外使用。

但这个过程需要有完善的可观测系统的支撑，比如日志、监控等，如果没有这些数据，再回头排查问题就会比较困难。

总之这个排查过程才是最主要的，大家还有什么排查问题的小 tips 也欢迎在评论区分享。