前幾天排查了一個業務介面執行高延遲的問題,也挺有參考意義的,分享一下排查過程。
現象是業務反饋有一個介面業務邏輯其實很簡單,但是呼叫一次耗時,如下圖所示:
排查應用執行狀態
首先第一步需要檢視當時的應用執行狀態,包含當時的日誌、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 也歡迎在評論區分享。