前言
前幾日早上開啟郵箱收到一封監控報警郵件:某某 ip 伺服器 CPU 負載較高,請研發儘快排查解決,傳送時間正好是凌晨。
其實早在去年我也處理過類似的問題,並記錄下來:《一次生產 CPU 100% 排查優化實踐》
不過本次問題產生的原因卻和上次不太一樣,大家可以接著往下看。
問題分析
收到郵件後我馬上登陸那臺伺服器,看了下案發現場還在(負載依然很高)。
於是我便利用這類問題的排查套路定位一遍。
首先利用 top -c
將系統資源使用情況實時顯示出來 (-c
引數可以完整顯示命令)。
接著輸入大寫 P
將應用按照 CPU
使用率排序,第一個就是使用率最高的程式。
果不其然就是我們的一個 Java
應用。
這個應用簡單來說就是定時跑一些報表使的,每天凌晨會觸發任務排程,正常情況下幾個小時就會執行完畢。
常規操作第二步自然是得知道這個應用中最耗 CPU
的執行緒到底再幹嘛。
利用 top -Hp pid
然後輸入 P
依然可以按照 CPU
使用率將執行緒排序。
這時我們只需要記住執行緒的 ID 將其轉換為 16 進位制儲存起來,通過 jstack pid >pid.log
生成日誌檔案,利用剛才儲存的 16 進位制程式 ID
去這個執行緒快照中搜尋即可知道消耗 CPU
的執行緒在幹啥了。
如果你嫌麻煩,我也強烈推薦阿里開源的問題定位神器 arthas
來定位問題。
比如上述操作便可精簡為一個命令 thread -n 3
即可將最忙碌的三個執行緒快照列印出來,非常高效。
更多關於 arthas 使用教程請參考官方文件。
由於之前忘記截圖了,這裡我直接得出結論吧:
最忙綠的執行緒是一個 GC
執行緒,也就意味著它在忙著做垃圾回收。
GC 檢視
排查到這裡,有經驗的老司機一定會想到:多半是應用記憶體使用有問題導致的。
於是我通過 jstat -gcutil pid 200 50
將記憶體使用、gc 回收狀況列印出來(每隔 200ms 列印 50次)。
從圖中可以得到以下幾個資訊:
Eden
區和old
區都快佔滿了,可見記憶體回收是有問題的。fgc
回收頻次很高,10s 之內發生了 8 次回收((866493-866485)/ (200 *5)
)。- 持續的時間較長,fgc 已經發生了 8W 多次。
記憶體分析
既然是初步定位是記憶體問題,所以還是得拿一份記憶體快照分析才能最終定位到問題。
通過命令 jmap -dump:live,format=b,file=dump.hprof pid
可以匯出一份快照檔案。
這時就得藉助 MAT
這類的分析工具出馬了。
問題定位
通過這張圖其實很明顯可以看出,在記憶體中存在一個非常大的字串,而這個字串正好是被這個定時任務的執行緒引用著。
大概算了一下這個字串所佔的記憶體為 258m 左右,就一個字串來說已經是非常大的物件了。
那這個字串是咋產生的呢?
其實看上圖中的引用關係及字串的內容不難看出這是一個 insert
的 SQL
語句。
這時不得不讚嘆 MAT
這個工具,他還能幫你預測出這個記憶體快照可能出現問題地方同時給出執行緒快照。
最終通過這個執行緒快照找到了具體的業務程式碼:
他呼叫一個寫入資料庫的方法,而這個方法會拼接一個 insert
語句,其中的 values
是迴圈拼接生成,大概如下:
<insert id="insert" parameterType="java.util.List">
insert into xx (files)
values
<foreach collection="list" item="item" separator=",">
xxx
</foreach>
</insert>
複製程式碼
所以一旦這個 list 非常大時,這個拼接的 SQL 語句也會很長。
通過剛才的記憶體分析其實可以看出這個 List
也是非常大的,也就導致了最終的這個 insert
語句佔用的記憶體巨大。
優化策略
既然找到問題原因那就好解決了,有兩個方向:
- 控制源頭
List
的大小,這個List
也是從某張表中獲取的資料,可以分頁獲取;這樣後續的insert
語句就會減小。 - 控制批量寫入資料的大小,其實本質還是要把這個拼接的
SQL
長度降下來。 - 整個的寫入效率需要重新評估。
總結
本次問題從分析到解決花的時間並不長,也還比較典型,其中的過程再總結一下:
- 首先定位消耗
CPU
程式。 - 再定位消耗
CPU
的具體執行緒。 - 記憶體問題
dump
出快照進行分析。 - 得出結論,調整程式碼,測試結果。
最後願大家都別接到生產告警。
你的點贊與分享是對我最大的支援