記一次Dubbo超時 CPU高負載問題排查

1.問題背景

最近經常有同事反饋我們灰度環境老的交易系統，這裡簡稱trade，dubbo消費者呼叫其他服務超時，因為該專案維護人員眾多，加上灰度環境發布較多，一直沒有排查，然後五一前再次有同事反饋這個問題，剛好有空就準備分析一下引起超時的原因。

2.問題排查

2-1 問題描述

大量dubbo服務呼叫超時

2-2 問題排查

檢視日誌（上圖）發現dubbo超時日誌裡面的兩個時間異常

client elapsed ,server elapsed 時間較長，加起來超過了timeout時間3s，導致服務超時，其中client elapsed 達到了699ms，看到這裡第一感覺是很驚訝，為啥消費者端會花費這麼長的時間

帶著這個疑問，首先確認了這個時間的計算邏輯，具體原始碼見附圖

error日誌資訊拼裝方法

defaultfuture類,

start = 例項化物件時初始化

可以看出，client elapsed：699ms，表示consumer future物件例項化到實際dosent之間耗時較長，所以這裡產生了乙個新的疑問：

為什麼這麼輕量化的邏輯卻要花費699ms甚至更長的時間完成？

帶著這個疑問，首先想到的是對伺服器當前負載進行確認

下圖為top命令截圖，可以看到cpu使用率在72%，

新的問題：cpu為啥使用率這麼高？

理論上來說灰度環境並沒有很大的呼叫量，僅開發和測試用到，80%甚至90%的使用率顯然不合理。當前排查重點變成了找出導致cpu高使用率的原因。

首先 top -h -p 22503，找到占用cpu的執行緒號 22509和22993

jstack找到占用cpu的對應的執行緒資訊分別是vm thread和netty

這裡vmthread 是虛擬機器執行緒，猜測是gc導致cpu使用率高

nettyclientworker應該是dubbo消費者的正常執行緒，暫時沒有分析

分析jvm gc資訊，2s一次查詢，發下full gc頻繁

分析gc日誌，發下full gc原因full gc (heap inspection initiated gc）

結合之前4-5s一次fullgc的頻率來看，推測應該是運維有某個指令碼在自動檢測

檢視當前有沒有在執行的jmap執行緒

發現原因jmap -histo:live 22503 和jmaplog.sh

遺憾的是jmaplog.sh 檔案以及被刪除，從時間上看，2023年便已經啟動了該執行緒。

猜測是當時跑過該指令碼但是一直忘記kill了。

觀察業務日誌：沒有發現超時異常

3.問題總結

jmap檢測指令碼導致 jvm一直在fgc，頻率大概在4-5s左右，每次fgc耗時0.6s左右導致伺服器整體負載被打滿，然後影響到dubbo服務

本文只是分析了引起dubbo超時的其中乙個原因，後來排查分析dubbo超時還有另乙個原因是因為有個dubbo慢sql查詢的呼叫在灰度大量呼叫（頻率高數量大），線上對該方法進行了限流1的qps，灰度沒有限流，該查詢方法本身就有問題，會導致超時。