記一次線上CPU超高的排查過程

最近發現公司一個主機的CPU每隔幾天就飈上去，致使機器上部署的服務不可用。

top
顯示進程18781佔用CPU超過190%（主機是雙核）。
top -Hp 18781
其中線程18783和18784各自的CPU都達到了99%。
jstack 18781 >> jstack.out
把JVM的線程信息導出到文件。

printf '%xn' 18783
printf '%xn' 18784
線程ID轉換成16進制

在導出的線程棧文件jstack.out裏查找495f和4960，對應的是gc線程，初步推斷是內存泄漏致使的頻繁gc。

jstat -gcutil 18781 1s

能夠看到每隔幾秒就會full gc，並且Eden和Old都是99%，就是說每次full gc都沒有回收到多少內存，因此一直在反覆的跑。

如今要把虛擬機內存導出，分析內存中是哪些對象佔用大量空間不釋放，由於HeapDump在生產環境是沒有打開的（幸虧沒有打開HeapDumpBeforeFullGC ，否則就不止是CPU高了，按這幾秒full gc一次的頻率，用不了多久把磁盤也要撐爆），因此要用到一個小工具jinfo。

jinfo是jdk中自帶的一個工具，用來查看運行中的虛擬機的參數，甚至在運行時動態修改一些JVM參數。
java -XX:+PrintFlagsFinal -version | grep manageable

選項-XX:+PrintFlagsFinal能夠列出全部的JVM flag，而其中的標註爲manageable 的flag則是可經過JDK management interface（-XX:+PrintFlagsFinal）動態修改。

用jinfo打開如下選項，把full gc先後的虛擬機內存dump下來。
jinfo -flag +PrintGC 18781
jinfo -flag +PrintGCDetails 18781
jinfo -flag HeapDumpPath=/home/work/data/heapdump 18781
jinfo -flag +HeapDumpBeforeFullGC 18781
jinfo -flag +HeapDumpAfterFullGC 18781

PrintGC和PrintGCDetails把gc日誌輸出到了nohup.out，查看nohup文件，能夠看到full gc先後各dump了一次虛擬機內存，而後趕忙用jinfo關掉gc選項，選項前+號表示打開，-號表示關閉。

jinfo -flag -HeapDumpBeforeFullGC 18781
jinfo -flag -HeapDumpAfterFullGC 18781

在HeapDumpPath下找到dump下來的hprof文件，用mat打開，Linux下沒有找到相關的工具，因此我先把文件下載到本機，用window版的mat打開。

SessionFactoryImpl佔了1個多G，超過99%。打開Reports>Leak Suspects

Retained Size=當前對象大小+當前對象可直接或間接引用到的對象的大小總和，因此問題出在第一項的引用鏈上。點這一項的List Objects>with incoming references.

這個queryPlanCache是hibernate對SQL語句的緩存，能夠參考stackoverflow上一位前輩的經驗，https://stackoverflow.com/que...，看來是太多數據庫in查詢形成了大量的SQL緩存，此時回頭再看線程棧stack.out的信息，確實有不少Running狀態的at com.sun.proxy.$Proxy131.findByIdIn(Unknown Source)，這樣就說的通了。

下一步，優化代碼吧。