在平時開發過程中,經常會碰到Java進程占用cpu過高的現象,本篇將簡單記錄一下自己分析該類問題的步驟。
1.使用 top -p <pid> 命令(<pid>為Java進程的id號)查看Java進程的cpu占用:
該Java進程占用cpu達到92.2%。
2.使用 top -Hp <pid> 命令(<pid>為Java進程的id號)查看該Java進程內所有線程的資源占用情況(按shft+p按照cpu占用進行排序,按shift+m按照內存占用進行排序)此處按照cpu排序:
可以看到,有兩個線程號為97243,97912的線程占用cpu分別達到了69.2%和22.0%
3.使用 printf "%x\n" <tid> 命令(tid指線程的id號)將以上10進制的線程號轉換為16進制:
轉換后的結果分別為17bdb,17e78,由於16進制以0x開頭,所以對應的16進制的線程號為0x17bdb和0x17e78。
4.使用dk自帶命令jstack獲取此時的線程快照並輸入到文件中: jstack -l <pid> > ./jstack_result.txt 命令(<pid>為Java進程的id號)來獲取線程快照結果並輸入到指定文件。
5.查看第4步生成的txt文件,在其中搜索tid為0x17bdb的線程:
可以看到線程號為0x17bdb(10進制線程號97243)對應的是一個"VM Thread"即虛擬機線程,這個不是與我們代碼相關的線程,所以暫時忽略。
再看0x17e78線程:
該線程的堆棧較深,且很明顯有調用我們自己代碼的邏輯,並且提示了具體的代碼行數,我們查看該處代碼:
發現此處是在一個死循環里邊重復的拼接字符串導致的,我們知道,String類使用contact方法拼接字符串其實是創建新的對象並返回,看到這里,似乎可以和占用cpu最高的"VM Thread"聯系起來了,因此作出假設:由於代碼一直循環創建對象,導致不斷有不再被引用的對象產生,虛擬機檢測到對象不再被引用之后,就進行垃圾回收,垃圾回收占用了很大一部分cpu資源。
為了證明該假設,設置jvisualvm監控,經過一段時間允許,cpu資源監控結果如下:
可以看到cpu總占用達到88.5%,而垃圾回收活動占用cpu達到84.0%,因此證明了上述假設。
知道了該問題的原因后,我們還想知道此時垃圾回收的頻率,耗時等信息,於是可以設置JVM參數 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log (或者使用jinfo命令動態設置GC日志,可參考http://www.importnew.com/15722.html),可以看到日志內容:
gc.log中頻繁的打印垃圾回收,不過我們看到的基本都是Minor GC,即新生代的垃圾回收。
為了更清晰的查看各個區的垃圾回收情況,可以使用jstat命令 jstat -gc <pid> <period> <count> (pid為Java進程的id,period指每次監控之間的時間間隔,count指監控次數)來監控垃圾回收,打印內容如下:
可以看到,虛擬機在進行頻繁的Full GC,每次耗時均在增長。
總結:
分析Java進程占用cpu過高問題時候,基本都可以按照如下步驟進行分析:
(1)使用 top -Hp <pid> 命令找出進程中占用cpu最高的前幾個線程
(2)使用jstack獲取線程快照,然后使用線程id搜索分析快照文件
(3)如果線程調用了業務相關代碼,則分析是否是代碼問題導致的cpu占用過高,如果線程是VM Thread,則應該監控檢查垃圾回收活動頻率,看是否是因為頻繁進行垃圾回收導致的。