通常情況下,效能報告中只說CPU使用率高的時候,並不能幫助定位問題。因為CPU高會有多種不同的情況。CPU有五種狀態(us sy id wa st), 在vmstat中能顯示出來,這個想必很多人都清楚。在程式碼消耗CPU的時候(這也是通常效能分析中會遇到的),是US狀態的CPU。當然還存在一種情況,就是程式碼產生的系統呼叫特別高,這種情況下SY的CPU也會高(這種情況比較少見,在我的職業生涯中只見過一次)。對於JAVA語言來說,我們不需要特別複雜的profile工具就可以做到定位到程式碼。
在寫具體的分析方法之前,需要說一下執行緒的狀態轉換關係,我們先來看一下系統級的執行緒狀態轉換關係。
通過這個轉換關係,可以看到,線上程產生之後,會先到ready的狀態。在這個狀態上是在等待CPU的。而在runing狀態才是真正在CPU上執行的。請注意這個區別。
而vmstat顯示的 r 列是包括了ready和running的執行緒(會因作業系統的不同有區別,但是對大部分linux系統都是這樣)。請注意這一點,因為網上有很多在寫vmstat的解釋的時候,說 r 列是表示正在執行的程式數或者說 r 是表示正在執行的執行緒數,這一點是不對的。給大家看一個例子(這也是下面要說到的例子):
這是我的一個雲伺服器上正在執行的top。可以看到當前tasks(程式)中只有一個是running的狀態的。而這時的vmstat呢?
這個伺服器只有兩個CPU,所以如果r是說正在執行的程式或執行緒數的話肯定是不正確的,因為兩個CPU同時執行的最多是兩個執行緒。
所以請記住,這個 r 值就包括了等待CPU的執行緒(也就是ready狀態的)和正在執行的執行緒(也就是running狀態的)。
以後有時間再解釋其他系統級的執行緒狀態,可能有些人覺得其他狀態也沒什麼好解釋的,但是在效能分析中,執行緒的狀態和一些效能計數器是有關聯關係的,比如說suspended狀態是CPU時間片用完導致暫時被換出;而blocked是因為要等待某個條件被滿足而阻塞;並且這兩種狀態都有可能導致CPU使用率高。在分析的過程中,這些資訊給我們的是一個方向。所以前面說到僅說CPU高不能幫助分析問題,因為CPU高有多種原因。
因為下面要說的是JAVA,所以來看一下JAVA的執行緒狀態轉換關係。
從這個圖中,我們可以看到JAVA的程式有多種狀態(具體狀態的解釋請自行搜尋),怎麼看到這些狀態都在幹什麼,就需要把棧打出來看。在棧中,可以看到具體對應的程式碼(對其他編譯語言來說,要看看到正在執行的code也是要看棧的)。另外,在效能分析中,棧的分析是非常重要的一塊內容,今天因為只是為了說明從CPU高怎麼定位到程式碼層,所以不過多解釋執行緒的狀態了,以後有時間再寫文章說明。
例項:
下面來操作一下,首先執行一個消耗CPU的JAVA例項(例項是7D Group成員所編,有興趣動手操作的可以到網上隨便找一個小例子或自己編寫一個)。檢視vmstat的狀態。
從上圖可以看到左邊視窗在執行一個消耗CPU的Demo,而右邊的視窗看到當前系統的CPU已經完全被消耗掉了。程式號通過top命令就可以知道:
下面就要看一下這個程式中的哪些執行緒消耗了CPU。
通過pidstat可以看到(不好意思的是,pidstat的截圖被我覆蓋掉了,又不想重新開始所以就不截圖啦),有10個執行緒消耗著CPU資源。我把命令放在這裡,有興趣的可以自己操作。
pidstat -p 10846 -u -d -t -w -h 1 1000
從上命令可以看到,有多個執行緒消耗著CPU。執行緒ID是:10861、10862、10863等等。
用jstack做一下thread dump。
[root@7dgroup ~]# jstack -l 10846 > 10846.threaddump
再開啟這個生成的檔案。
nid是指native ID,對應著系統級的tid。只不過TID顯示的是10程式的,NID顯示的是16進位制的。
我們轉換一個執行緒號來查詢。
[root@7dgroup ~]# printf %x'\n' 10861
2a6d
再對應到threaddump檔案中。
顯然可以去查這個CPUTestThreadDemo.java的第13行了。
從這個例子可以看出,對java的程式碼消耗CPU高的分析只需要通過系統級的命令和JDK自帶的命令就可以完成了。因為這個例子非常簡單,步驟比較清楚。但在實際分析程式碼眾多,邏輯複雜的應用,有可能你看到的是CPU線上程上的消耗是在不停的切換的,所以就需要多做些thread dump,一個個分析。當然藉助些工具分析,通常可以讓我們在分析複雜的應用時事半功倍。
這裡只說明一個思路。
對JAVA的分析來說,已經有非常多的人寫了非常多的文章了,我之所以寫這個文章,是為了讓文章能更系列一些。