前幾日早上打開郵箱收到一封監控報警郵件:某某 ip 服務器 CPU 負載較高,請研發儘快排查解決,發送時間正好是凌晨。java
其實早在去年我也處理過相似的問題,並記錄下來:《一次生產 CPU 100% 排查優化實踐》git
不過本次問題產生的緣由卻和上次不太同樣,你們能夠接着往下看。github
收到郵件後我立刻登錄那臺服務器,看了下案發現場還在(負載依然很高)。數據庫
因而我便利用這類問題的排查套路定位一遍。服務器
首先利用 top -c
將系統資源使用狀況實時顯示出來 (-c
參數能夠完整顯示命令)。工具
接着輸入大寫 P
將應用按照 CPU
使用率排序,第一個就是使用率最高的程序。測試
果不其然就是咱們的一個 Java
應用。優化
這個應用簡單來講就是定時跑一些報表使的,天天凌晨會觸發任務調度,正常狀況下幾個小時就會運行完畢。spa
常規操做第二步天然是得知道這個應用中最耗 CPU
的線程到底再幹嗎。線程
利用 top -Hp pid
而後輸入 P
依然能夠按照 CPU
使用率將線程排序。
這時咱們只須要記住線程的 ID 將其轉換爲 16 進制存儲起來,經過 jstack pid >pid.log
生成日誌文件,利用剛纔保存的 16 進制進程 ID
去這個線程快照中搜索便可知道消耗 CPU
的線程在幹啥了。
若是你嫌麻煩,我也強烈推薦阿里開源的問題定位神器 arthas
來定位問題。
好比上述操做即可精簡爲一個命令 thread -n 3
便可將最忙碌的三個線程快照打印出來,很是高效。
更多關於 arthas 使用教程請參考官方文檔。
因爲以前忘記截圖了,這裏我直接得出結論吧:
最忙綠的線程是一個 GC
線程,也就意味着它在忙着作垃圾回收。
排查到這裏,有經驗的老司機必定會想到:多半是應用內存使用有問題致使的。
因而我經過 jstat -gcutil pid 200 50
將內存使用、gc 回收情況打印出來(每隔 200ms 打印 50次)。
從圖中能夠獲得如下幾個信息:
Eden
區和 old
區都快佔滿了,可見內存回收是有問題的。fgc
回收頻次很高,10s 以內發生了 8 次回收((866493-866485)/ (200 *5)
)。既然是初步定位是內存問題,因此仍是得拿一分內存快照分析才能最終定位到問題。
經過命令 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
出快照進行分析。最後願你們都別接到生產告警。
你的點贊與分享是對我最大的支持