為了進行測試,我們將使用以下簡單程序:
public class Main {public static void main(String[] args) {new Thread(new Idle(), 'Idle').start();new Thread(new Busy(), 'Busy').start();}
}class Idle implements Runnable {@Overridepublic void run() {try {TimeUnit.HOURS.sleep(1);} catch (InterruptedException e) {}}
}class Busy implements Runnable {@Overridepublic void run() {while(true) {'Foo'.matches('F.*');}}
}
如您所見,它啟動了兩個線程。 Idle
不消耗任何CPU(請記住,睡眠線程消耗內存,但不消耗CPU),而Busy
占用整個內核,因為正則表達式的解析和執行是一個令人驚訝的復雜過程。 讓我們運行該程序,然后將其忽略。 我們如何快速發現Busy
是我們軟件中有問題的部分? 首先,我們使用top來找出消耗大部分CPU的java
進程的進程ID( PID
)。 這很簡單:
$ top -n1 | grep -m1 java
這將顯示包含“ java
”語句的top
輸出的第一行:
22614 tomek 20 0 1360m 734m 31m S 6 24.3 7:36.59 java
第一列是PID,讓我們提取它。 不幸的是,事實證明top
使用ANSI轉義碼表示顏色 –看不見的字符破壞了grep
和cut
類的工具。 幸運的是,我找到了一個Perl腳本來刪除這些字符 ,并最終能夠提取用盡CPU的java
進程的PID:
$ top -n1 | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '
cut -f1 -d' '
調用只是將第一個值從以空格分隔的列中取出:
22614
現在,當我們遇到有問題的JVM PID時,我們可以使用top -H
查找有問題的Linux線程。 -H
選項顯示與進程相對的所有線程的列表,PID列現在表示內部Linux線程ID:
$ top -n1 -H | grep -m1 java
$ top -n1 -H | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '
輸出令人驚訝地相似,但是第一個值現在是線程ID:
25938 tomek 20 0 1360m 748m 31m S 2 24.8 0:15.15 java
25938
因此,我們有一個繁忙的JVM的進程ID和Linux線程ID(很可能來自該進程)消耗了我們的CPU。 這是最好的部分:如果查看jstack輸出(在JDK中可用),則每個線程的名稱旁邊都會印有一些神秘的ID:
'Busy' prio=10 tid=0x7f3bf800 nid=0x6552 runnable [0x7f25c000]java.lang.Thread.State: RUNNABLEat java.util.regex.Pattern$Node.study(Pattern.java:3010)
沒錯, nid=0x645a
參數與top -H
打印的線程ID相同。 當然,不要太簡單,在jstack
以十六進制打印時, top
使用十進制表示法。 再次有一個簡單的解決方案, printf'%x' :
$ printf '%x' 25938
6552
讓我們將我們現在擁有的所有內容包裝到一個腳本中并合并結果:
#!/bin/bash
PID=$(top -n1 | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' ')
NID=$(printf '%x' $(top -n1 -H | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '))
jstack $PID | grep -A500 $NID | grep -m1 '^$' -B 500
PID
持有java
PID, NID
持有線程ID,很可能來自該JVM。 最后一行只是轉儲給定PID的JVM堆棧跟蹤,并過濾(使用grep
)具有相匹配的nid
的線程。 猜猜它有什么用:
$ ./profile.sh
'Busy' prio=10 tid=0x7f3bf800 nid=0x6552 runnable [0x7f25c000]java.lang.Thread.State: RUNNABLEat java.util.regex.Pattern$Node.study(Pattern.java:3010)at java.util.regex.Pattern$Curly.study(Pattern.java:3854)at java.util.regex.Pattern$CharProperty.study(Pattern.java:3355)at java.util.regex.Pattern$Start.<init>(Pattern.java:3044)at java.util.regex.Pattern.compile(Pattern.java:1480)at java.util.regex.Pattern.<init>(Pattern.java:1133)at java.util.regex.Pattern.compile(Pattern.java:823)at java.util.regex.Pattern.matches(Pattern.java:928)at java.lang.String.matches(String.java:2090)at com.blogspot.nurkiewicz.Busy.run(Main.java:27)at java.lang.Thread.run(Thread.java:662)
多次運行腳本(或使用watch
,請參見下文)將在不同位置捕獲Busy
線程,但是幾乎總是在正則表達式解析中進行–這是我們有問題的部分!
多線程
如果您的應用程序具有多個需要CPU的線程,則可以使用watch -n1 ./profile.sh
命令watch -n1 ./profile.sh
運行一次腳本并獲取半實時堆棧轉儲,這很可能來自不同的線程。 使用以下程序進行測試:
new Thread(new Idle(), 'Idle').start();
new Thread(new Busy(), 'Busy-1').start();
new Thread(new Busy(), 'Busy-2').start();
您將看到Busy-1
或Busy-2
線程的堆棧跟蹤(在Pattern
類中的不同位置),但是從不Idle
。
參考: 哪個Java線程消耗了我的CPU? 來自我們的JCG合作伙伴 Tomasz Nurkiewicz,來自Java和鄰里博客。
翻譯自: https://www.javacodegeeks.com/2012/08/which-java-thread-consumes-my-cpu.html