前幾天排查了一個業(yè)務接口執(zhí)行高延遲的問題，也挺有參考意義的，分享一下排查過程。

現(xiàn)象是業(yè)務反饋有一個接口業(yè)務邏輯其實很簡單，但是調(diào)用一次耗時，如下圖所示：

圖片

排查應用運行狀態(tài)

首先第一步需要查看當時的應用運行狀態(tài)，包含當時的日志、JVM 的各種監(jiān)控等。

因為我們接入了 OpenTelemetry，所以 trace 和日志是可以關聯(lián)起來的。

點擊鏈路系統(tǒng)旁邊的日志按鈕可以直接跳轉(zhuǎn)。

可以通過 trace_id 查詢到相關日志：

圖片

通過日志可以看出耗時大約在 4s 多一點，然后結合代碼發(fā)現(xiàn)這兩段日志分別是在進入一個核心業(yè)務方法之前和方法內(nèi)打印的。

圖片

而第一行日志是在一個自定義限流器中打印的，這個限流器是使用 Guava 的 RateLimiter實現(xiàn)的。

我的第一反應是不是這個限流器當時限流了，從而導致阻塞了；但查看了當時的 QPS 發(fā)現(xiàn)完全低于限流器的配置，所以基本可以排除它的嫌疑了。

JVM 監(jiān)控

圖片

圖片

之后我們查詢當時的 JVM 監(jiān)控發(fā)現(xiàn)當時的 GC  頻繁，而堆內(nèi)存也正好發(fā)生了一次回收，初步判斷是 GC 導致的本次問題。

但為啥會導致頻繁的 GC 呢，還需要繼續(xù)排查。

內(nèi)存排查

我們在應用診斷中集成了 Pyroscope的持續(xù)剖析，可以實時查看內(nèi)存的占用情況。

圖片

圖片

通過內(nèi)存分析發(fā)現(xiàn)有大量的 JSON 序列化占用了大量的內(nèi)存，同時還發(fā)現(xiàn) Pod 已經(jīng)被重啟好幾次了：

圖片

圖片

查看原因發(fā)現(xiàn)是 Pod OOM 導致的。

因此非常有可能是 GC 導致的，恰好那段時間發(fā)生了 GC 內(nèi)存也有明顯變化。

圖片

圖片

圖片

最后再通過 arthas 確認了 GC 非常頻繁，可以確認目前的資源是是非常緊張的，咨詢業(yè)務之后得知該應用本身占用的資源就比較大，沒有太多優(yōu)化空間，所以最終決定還是加配置。

圖片

圖片

還是提高硬件效率最高，目前運行半個月之后 Pod 內(nèi)存表現(xiàn)穩(wěn)定，沒有出現(xiàn)一次 OOM 的異常。

總結

雖然最后的處理的方式是簡單粗暴的，但其中的過程還是有意義的，遇到不同的情況也有不同的處理方式。

比如在排查過程中發(fā)現(xiàn)內(nèi)存消耗異常，通過內(nèi)存分析發(fā)現(xiàn)代碼可以優(yōu)化，那就優(yōu)化代碼邏輯。

如果是堆內(nèi)存占用不大，但是 Pod 還是 OOM 導致重啟，那就要看看 JVM 的內(nèi)存分配是否合理，應該多預留一些內(nèi)存給堆外使用。

但這個過程需要有完善的可觀測系統(tǒng)的支撐，比如日志、監(jiān)控等，如果沒有這些數(shù)據(jù)，再回頭排查問題就會比較困難。