1. 程式人生 > >一次線上的GC問題排查

一次線上的GC問題排查

6.19號下午 線上系統出現了一次實時鏈路資料 不通暢的問題, 業務方反應更新的增量資料沒有流入到HA3搜尋叢集
登入機器後檢查日誌後發現,在週六晚上到周天下午,cr_search_merge(機器人schema統一)表增量資料猛增,初步估計瞬間壓在DRC-reader上的資料達百萬級別的量
DRC-reader 應用會不間斷的報 :

blob.png

和 下面的錯誤:

blob.png

這2個錯誤都是之前未曾出現過的錯誤

嘗試重啟應用後,隔幾分鐘後出現相同的錯.

線上 DRC-reader 的原理如下圖: 

download.png

原理:  程式從DRC 讀取資料後, 經過不同步驟的資料處理後,通過多個管道不停的往後傳輸,最終達到輸出器輸出在不同的持久化介質上。輸出器在把資料輸出到介質時,會雙寫時間戳到ZK,應用重啟時,從該時間戳的點位開始讀

,這樣可以解決在應用重啟時或機器崩潰時記憶體中的資料丟失的問題。

第一個錯定位到日誌列印處,分析程式碼後發現:當最後一個數據處理佇列(上圖中的 LBQueue writeRecords 佇列)的容量達到限定的容量後,會丟擲這個異常,並中斷程式.

於是嘗試把最後一個佇列的限制長度調大,從1W調到100W , 重啟應用第一個錯不再出現。

但寫ZK的錯依然在報,再次調整配置引數: 

(1) 把ZK的寫時間戳間隔加大,

(2)把ZK的啟動時間戳改寫到1個小時前. 

這個錯也不再報了, 但輸出器輸出到持久化介質的速度非常慢,在經過幾個小時的消化後,系統恢復正常,資料正常流轉。

由於出問題時正值團隊在外outing,只能通過調系統引數來規避這些問題。

週二回到公司後,嘗試來重現當時的場景。 於是找了一臺測試機器,把DRC的時間戳定位到一天前,把系統引數調回去,另外添加了些JVM DEBUG引數,把GC日誌打印出來,儲存系統崩潰時的記憶體快照。執行系統,果然問題復現了。

top 指令結果如下:

G1.png

load升高,CPU飆升,系統卡死,同時應用日誌報如下的錯:

G5.png

這個錯很明顯了,有GC問題,於是, 執行下面的命令,把記憶體dump下來分析
jmap -J-d64 -dump:format=b,file=dump.bin 23218

用 jvisualvm分析發現:

G2.png

發現雖然最後的管道限制了長度為10000,但中間的管道訊息數量堆積達到了25W,這些資料堆積在記憶體裡,使得JVM頻繁GC,佔據了大量的CPU時間。

現在的架構使得,前面的DRC入口處並不知道後面管道的容量情況,無法對系統進行保護,不斷的放入資料到系統,記憶體瞬間暴增,發生了GC問題。

資料流入系統的速度 比 系統輸出資料的速度快,系統本身並未做限流措施,是本次GC問題的根本原因。

我做了個簡單的統計(單機): 

    流入的速度 大概高峰期間每秒可達:  3500/QPS

    流出的速度: 最後一根管道輸出器:  單執行緒的情況下,250QPS左右. 

                                                           開到三個執行緒併發輸出: 400QPS左右

    這中間的差異會導致訊息堆積,堆積在記憶體到一定量後必然發生GC問題,GC問題會進一步導致輸出QPS降低,產生惡性迴圈。

解決方案:

在系統內部 和 外部進行限流。

內部: 在讀取DRC資料入口處,通過介面拿到中間管道的佇列長度,進行限流(目前限制1W)。

外部: 依賴外部的系統承受能力,和相關同學溝通,限流500左右.

做完這些工作後,再次執行系統,觀察系統指標:

G4.png

系統執行比較平穩了,上述的錯誤均未再出現。

後續會進一步提升輸出器的併發能力,把這個提升上去後,可調高限流引數引數,使得整個系統的吞吐資料的能力提高