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

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

圖片

排查應(yīng)用運(yùn)行狀態(tài)

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

因?yàn)槲覀兘尤肓?OpenTelemetry，所以 trace 和日志是可以關(guān)聯(lián)起來(lái)的。

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

可以通過(guò) trace_id 查詢(xún)到相關(guān)日志：

圖片

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

圖片

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

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

JVM 監(jiān)控

圖片

圖片

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

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

內(nèi)存排查

我們?cè)趹?yīng)用診斷中集成了 Pyroscope的持續(xù)剖析，可以實(shí)時(shí)查看內(nèi)存的占用情況。

圖片

圖片

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

圖片

圖片

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

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

圖片

圖片

圖片

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

圖片

圖片

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

總結(jié)

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

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

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

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