摘要：前言前幾日早上打開郵箱收到一封監控報警郵件某某服務器負載較高，請研發盡快排查解決，發送時間正好是凌晨。其實早在去年我也處理過類似的問題，并記錄下來一次生產排查優化實踐不過本次問題產生的原因卻和上次不太一樣，大家可以接著往下看。

前幾日早上打開郵箱收到一封監控報警郵件：某某 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 線程，也就意味著它在忙著做垃圾回收。

排查到這里，有經驗的老司機一定會想到：多半是應用內存使用有問題導致的。

于是我通過 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 into xx (files)
        values
        
            xxx
        
    

所以一旦這個 list 非常大時，這個拼接的 SQL 語句也會很長。

通過剛才的內存分析其實可以看出這個 List 也是非常大的，也就導致了最終的這個 insert 語句占用的內存巨大。

既然找到問題原因那就好解決了，有兩個方向：

控制源頭 List 的大小，這個 List 也是從某張表中獲取的數據，可以分頁獲取；這樣后續的 insert 語句就會減小。

控制批量寫入數據的大小，其實本質還是要把這個拼接的 SQL 長度降下來。

整個的寫入效率需要重新評估。

本次問題從分析到解決花的時間并不長，也還比較典型，其中的過程再總結一下：

首先定位消耗 CPU 進程。

再定位消耗 CPU 的具體線程。

內存問題 dump 出快照進行分析。

得出結論，調整代碼，測試結果。

最后愿大家都別接到生產告警。

你的點贊與分享是對我最大的支持