最近在測試一個用java語言實現的數據采集接口時發現,接口一旦運行起來,CPU利用率瞬間飆升到85%-95%,一旦停止就恢復到40%以下,這讓我不得不面對以前從未關注過的程序性能問題。
在硬着頭皮查找資料定位錯誤修正bug的過程中參考了下面兩篇文章:
windows下揪出java程序占用cpu很高的線程 並找到問題代碼 死循環線程代碼:http://blog.csdn.net/hexin373/article/details/8846919
java程序cpu占用過高問題分析:http://www.tuicool.com/articles/ZRzmAvZ(這篇文章中的圖片顯示不了)
最初想通過java自帶的jconsole和jvisualvm來調試,但發現jconsole只能知道應用整體情況,不能定位問題,而jvisualvm最多查找到類,
如果所示,但不能更詳細的進行定位。於是參考了上面兩篇文章一步步實現了最終目的。
一、查找進程
查找問題進程比較簡單,因為問題集中在CPU資源占用過高,那么我們查找進程時只需關注CPU。方法有兩種:
1、查看Windows任務管理器
打開Windows任務管理器,查看——>選擇列,勾選PID,然后查看進程項,並讓其按照CPU列排序如圖,找到 javaw.exe進程,其PID是9272。
2、利用jvisualvm工具
打開工具,然后啟動應用,在Applications面板中即可看到應用所在進程的PID9272。
需要注意的是該工具並不能定位到線程。
查找到進程以后,將該進程的信息保存到本地,在cmd命令窗口中執行命令:jstack 9272 > C:\test\cdf.log,該命令的作用是將PID為9272的進程信息保存在本地C:\test\cdf.log文件中。
二、查找線程
根據進程查找線程,也有兩種方法。
1、使用window自帶命令pslist
首先確認系統是否安裝了pslist命令程序,如果命令不識別即沒有安裝,則上微軟官方網址http://technet.microsoft.com/en-us/sysinternals/bb896682.aspx下載,下載完將其解壓到C:\Windows\System32路徑下即可使用。
在cmd命令窗口中執行命令:pslist -dmx 9272,該命令的作用是羅列屬於9272進程的線程信息。
通過該命令可以看到TID為9368和12484的線程占用資源最多。這樣就基本確定了線程。
2、利用微軟提供的Process Explorer工具
一般在windows下只能查看進程的CPU占用率,想要查看線程的CPU占用率可以通過該工具。下載地址是:http://technet.microsoft.com/en-us/sysinternals/bb896653.aspx
下載后運行起來,找到PID為9272的進程
右鍵點擊Properties...選項,看到如下信息:
可以看到占用CPU最多的也是TID為9368和12484的兩個線程。
三、問題定位
問題定位需要以下步驟:
1、將線程TID轉換為十六進制
因為通過jstack工具導出的信息中線程TID是十六進制的,所以我們首先轉換進制,這里通過系統自帶的計算器進行轉換。
記錄下2498這個數字。
2、在jstack工具導出的cdf.log中查找“2498”
通過Notepad++工具打開該文檔,搜索到如下信息,可以看到問題定位到了MQStart.java:174。
去程序中需找該代碼:
同理,對於TID=12484的線程也如同以上步驟進行查找,找到了170行代碼。
由此基本可判斷問題就出在了該段代碼上。
四、修復bug
1、查找原因
通過以上步驟已經定位到了代碼片段,但是這段代碼看上去沒什么錯誤,查找資料說很多情況是進入死循環了,但是這里確定不會死循環。思路似乎進入了死胡同。
無奈之下我將170行的if內的代碼段全注釋掉了,發現CPU依然飆高,這說明並不是這幾行代碼的錯誤,然后我if內做了一個輸出操作,發現程序快速的不間斷的進行輸出。
====》
看到這個結果我突然醒悟,這段代碼雖然沒有進入死循環,但是循環內的代碼並不復雜,而且沒必要如此頻繁的進行檢查操作,這中間應該停歇一下。
2、修改方法
根據以上分析,我修改了這段代碼:
再次運行測試發現CPU維持在50%以內。