摘要：前言前幾日早上打開(kāi)郵箱收到一封監(jiān)控報(bào)警郵件某某服務(wù)器負(fù)載較高，請(qǐng)研發(fā)盡快排查解決，發(fā)送時(shí)間正好是凌晨。其實(shí)早在去年我也處理過(guò)類(lèi)似的問(wèn)題，并記錄下來(lái)一次生產(chǎn)排查優(yōu)化實(shí)踐不過(guò)本次問(wèn)題產(chǎn)生的原因卻和上次不太一樣，大家可以接著往下看。

前幾日早上打開(kāi)郵箱收到一封監(jiān)控報(bào)警郵件：某某 ip 服務(wù)器 CPU 負(fù)載較高，請(qǐng)研發(fā)盡快排查解決，發(fā)送時(shí)間正好是凌晨。

其實(shí)早在去年我也處理過(guò)類(lèi)似的問(wèn)題，并記錄下來(lái)：《一次生產(chǎn) CPU 100% 排查優(yōu)化實(shí)踐》

不過(guò)本次問(wèn)題產(chǎn)生的原因卻和上次不太一樣，大家可以接著往下看。

收到郵件后我馬上登陸那臺(tái)服務(wù)器，看了下案發(fā)現(xiàn)場(chǎng)還在（負(fù)載依然很高）。

于是我便利用這類(lèi)問(wèn)題的排查套路定位一遍。

首先利用 top -c 將系統(tǒng)資源使用情況實(shí)時(shí)顯示出來(lái) （-c 參數(shù)可以完整顯示命令）。

接著輸入大寫(xiě) P 將應(yīng)用按照 CPU 使用率排序，第一個(gè)就是使用率最高的程序。

果不其然就是我們的一個(gè) Java 應(yīng)用。

這個(gè)應(yīng)用簡(jiǎn)單來(lái)說(shuō)就是定時(shí)跑一些報(bào)表使的，每天凌晨會(huì)觸發(fā)任務(wù)調(diào)度，正常情況下幾個(gè)小時(shí)就會(huì)運(yùn)行完畢。

常規(guī)操作第二步自然是得知道這個(gè)應(yīng)用中最耗 CPU 的線程到底再干嘛。

利用 top -Hp pid 然后輸入 P 依然可以按照 CPU 使用率將線程排序。

這時(shí)我們只需要記住線程的 ID 將其轉(zhuǎn)換為 16 進(jìn)制存儲(chǔ)起來(lái)，通過(guò) jstack pid >pid.log 生成日志文件，利用剛才保存的 16 進(jìn)制進(jìn)程 ID 去這個(gè)線程快照中搜索即可知道消耗 CPU 的線程在干啥了。

如果你嫌麻煩，我也強(qiáng)烈推薦阿里開(kāi)源的問(wèn)題定位神器 arthas 來(lái)定位問(wèn)題。

比如上述操作便可精簡(jiǎn)為一個(gè)命令 thread -n 3 即可將最忙碌的三個(gè)線程快照打印出來(lái)，非常高效。

更多關(guān)于 arthas 使用教程請(qǐng)參考官方文檔。

由于之前忘記截圖了，這里我直接得出結(jié)論吧：

最忙綠的線程是一個(gè) GC 線程，也就意味著它在忙著做垃圾回收。

排查到這里，有經(jīng)驗(yàn)的老司機(jī)一定會(huì)想到：多半是應(yīng)用內(nèi)存使用有問(wèn)題導(dǎo)致的。

于是我通過(guò) jstat -gcutil pid 200 50 將內(nèi)存使用、gc 回收狀況打印出來(lái)（每隔 200ms 打印 50次）。

從圖中可以得到以下幾個(gè)信息：

Eden 區(qū)和 old 區(qū)都快占滿(mǎn)了，可見(jiàn)內(nèi)存回收是有問(wèn)題的。

fgc 回收頻次很高，10s 之內(nèi)發(fā)生了 8 次回收（(866493-866485)/ (200 *5)）。

持續(xù)的時(shí)間較長(zhǎng)，fgc 已經(jīng)發(fā)生了 8W 多次。

既然是初步定位是內(nèi)存問(wèn)題，所以還是得拿一份內(nèi)存快照分析才能最終定位到問(wèn)題。

通過(guò)命令 jmap -dump:live,format=b,file=dump.hprof pid 可以導(dǎo)出一份快照文件。

這時(shí)就得借助 MAT 這類(lèi)的分析工具出馬了。

通過(guò)這張圖其實(shí)很明顯可以看出，在內(nèi)存中存在一個(gè)非常大的字符串，而這個(gè)字符串正好是被這個(gè)定時(shí)任務(wù)的線程引用著。

大概算了一下這個(gè)字符串所占的內(nèi)存為 258m 左右，就一個(gè)字符串來(lái)說(shuō)已經(jīng)是非常大的對(duì)象了。

那這個(gè)字符串是咋產(chǎn)生的呢？

其實(shí)看上圖中的引用關(guān)系及字符串的內(nèi)容不難看出這是一個(gè) insert 的 SQL 語(yǔ)句。

這時(shí)不得不贊嘆 MAT 這個(gè)工具，他還能幫你預(yù)測(cè)出這個(gè)內(nèi)存快照可能出現(xiàn)問(wèn)題地方同時(shí)給出線程快照。

最終通過(guò)這個(gè)線程快照找到了具體的業(yè)務(wù)代碼：

他調(diào)用一個(gè)寫(xiě)入數(shù)據(jù)庫(kù)的方法，而這個(gè)方法會(huì)拼接一個(gè) insert 語(yǔ)句，其中的 values 是循環(huán)拼接生成，大概如下：

    
        insert into xx (files)
        values
        
            xxx
        
    

所以一旦這個(gè) list 非常大時(shí)，這個(gè)拼接的 SQL 語(yǔ)句也會(huì)很長(zhǎng)。

通過(guò)剛才的內(nèi)存分析其實(shí)可以看出這個(gè) List 也是非常大的，也就導(dǎo)致了最終的這個(gè) insert 語(yǔ)句占用的內(nèi)存巨大。

既然找到問(wèn)題原因那就好解決了，有兩個(gè)方向：

控制源頭 List 的大小，這個(gè) List 也是從某張表中獲取的數(shù)據(jù)，可以分頁(yè)獲取；這樣后續(xù)的 insert 語(yǔ)句就會(huì)減小。

控制批量寫(xiě)入數(shù)據(jù)的大小，其實(shí)本質(zhì)還是要把這個(gè)拼接的 SQL 長(zhǎng)度降下來(lái)。

整個(gè)的寫(xiě)入效率需要重新評(píng)估。

本次問(wèn)題從分析到解決花的時(shí)間并不長(zhǎng)，也還比較典型，其中的過(guò)程再總結(jié)一下：

首先定位消耗 CPU 進(jìn)程。

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

內(nèi)存問(wèn)題 dump 出快照進(jìn)行分析。

得出結(jié)論，調(diào)整代碼，測(cè)試結(jié)果。

最后愿大家都別接到生產(chǎn)告警。

你的點(diǎn)贊與分享是對(duì)我最大的支持