（轉）線上linux系統故障排查之一：CPU使用率過高

原文：https://www.jianshu.com/p/6d573e42310a

一、通過top命令定位占用cpu高的進程

執行top命令得到以下結果：

 

top命令執行結果

通過上圖可以明顯看出進程PID41843占用cpu過高，明顯存在問題，定位到了進程id。當然如果你想只觀察進程PID41843的CPU和內存以及負載情況，可以使用以下命令

top -p 41843。

結果如下：

 

top -p 41843命令執行結果

這里順便解釋下上圖各個參數的意義，有利於讀者更好的排查問題。

1. 第一行是任務隊列信息
   top - 14:06:34 up 537 days, 6 min, 6 users, load average: 0.41, 0.45, 0.43

任務隊列信息	含義
14:06:34	當前時間
537 days	系統運行時間
6 min	用戶在線時間
6 users	在線用戶數
load average: 0.41, 0.45, 0.43	系統負載，即任務隊列的平均長度。1分鍾前、5分鍾前、15分鍾前平均負載

2)第二行為進程的信息

進程信息	含義
Tasks: 1 total	進程總數
0 running	正在運行的進程數
1 sleeping	睡眠的進程數
0 stopped	停止的進程數
0 zombie	僵屍進程數

3. 第三行為cpu信息

cpu信息	含義
6.1% us	用戶空間占用CPU百分比
1.5% sy	內核空間占用CPU百分比
0.0% ni	用戶進程空間內改變過優先級的進程占用CPU百分比
92.2% id	空閑CPU百分比
0.0% wa	等待輸入輸出的CPU時間百分比
0.0% hi	硬件中斷
0.0% si	軟件中斷
0.0%st	實時

4. 第四、五行為內存信息。
   內容如下：

物理內存信息	含義
Mem: 191272k total	物理內存總量
173656k used	使用的物理內存總量
17616k free	空閑內存總量
22052k buffers	用作內核緩存的內存量

交換區信息	含義
Swap: 192772k total	交換區總量
0k used	使用的交換區總量
192772k free	空閑交換區總量
123988k cached	緩沖的交換區總量

二、通過top命令定位問題進程中每個線程占用cpu情況

通過問題進程中每個線程占用cpu情況使用可以使用如下命令：

top -p 41843 -H

查看進程PID41843的每一個線程占用CPU情況，如圖。

 

top -p 41843 -H的執行結果

由上圖明顯可以發現，線程PID41892CPU占用率最高，接下來定位該線程的代碼是否出現異常導致cpu占用過高。

三、通過jstack 命令定位問題代碼

上一步發現PID41892占用的CPU過高，就將這個PID轉換成16進制，易知，PID41892轉化成16進制為a3a4。使用如下命令命令定位問題代碼：

jstack 41892 | grep a3a4

輸出如下：

"Thread" prio=10 tid=0x00007f950043e000 nid=0x54ee in test()；

可以分析得到： 線程Thread下的wait()函數cpu使用率很高，查看源代碼中的test()函數代碼如下：

public void test(){ while(true){ for(int i = 0 ;i<100;i++); } } 

while循環無法結束，一直搶占cpu，導致程序cpu使用過高，修改代碼即可。
到此為止，因為代碼問題導致的cpu使用過高的故障排查方法就介紹完了。

tips:由於內存的原因，頻繁的GC，也可能導致cpu使用過高，內存的解決方案在文章《線上linux系統故障排查之二：內存占用過高》中介紹。

四、終極大殺器

筆者是喜歡一、二、三步驟定位cpu使用率過高的問題，但是如果讀者覺得以上方法不喜歡或者以上無法定位問題時，可以使用jstack方法獲取進程PID41843包含的運行線程的所有狀態。使用如下命令：

jstack -l 41843
或者將結果輸入在dump.txt文檔中：jstack -l 41843 >> dump.txt

首先我們來介紹下，Jstack的輸出中，Java線程狀態的四種狀態的概念：

RUNNABLE 線程運行中或I/O等待
BLOCKED 線程在等待monitor鎖(synchronized關鍵字)
TIMED_WAITING 線程在等待喚醒，但設置了時限
WAITING 線程在無限等待喚醒

接下來用簡單的代碼模擬這4種狀態的發生，同時介紹下問題的排查方法。
1） 讓線程一直處於RUNNABLE狀態

public static void main(String[] args) { printPId();//打印進程id runnable();//模擬RUNNABLE狀態方法，第14行 } public static void runnable(){//第19行 int i = 0; while (true) { i++; } } public static void printPId() { String name = ManagementFactory.getRuntimeMXBean().getName(); System.out.println(name.split("@")[0]); } 

執行main函數，使用命令jstack -l PID(pid為printPId函數打印的值)，得到以下輸出信息：狀態為RUNNABLE，程序在Test類的runnable()方法中占用cpu，一般該狀態不會出現問題。但是如果多次執行該命令，發現cpu在持續執行該方法，且cpu使用過高，可以排查runnable()方法是否存在死循環等持續占用cpu的情況。

"main" #1 prio=5 os_prio=0 tid=0x00000000023fe000 nid=0x2ab8 runnable [0x0000000
0026df000]
java.lang.Thread.State: RUNNABLE
at Test.runnable(Test.java:19)
at Test.main(Test.java:14)

Locked ownable synchronizers:
-None

2） 讓線程一直處於BLOCKED狀態（重點關注）

public static void main(String[] args) { printPId();//打印進程id blocked();//模擬BLOCKED狀態方法，第16行 } public static void blocked(){ Integer lock = 0; new Thread() { public void run() { synchronized (lock) { try { Thread.sleep(1000 * 1000);//26行 } catch (Exception e) { e.printStackTrace(); } } } }.start(); try { Thread.sleep(100); } catch (Exception e) {e.printStackTrace();} synchronized (lock) { try { Thread.sleep(10 * 1000);//第37行 } catch (Exception e) { e.printStackTrace(); } } } public static void printPId() { String name = ManagementFactory.getRuntimeMXBean().getName(); System.out.println(name.split("@")[0]); } 

主線程sleep，先讓另外一個線程拿到lock，並長期持有lock（sleep會持有鎖，wait不會）。此時主線程會BLOCK住等待lock被釋放，此時jstack的輸出可以看到main線程狀態是BLOCKED。
根據以下輸出可以看出：
1）線程狀態是 Blocked，阻塞狀態。說明線程等待資源超時！
2）“ waiting to lock <0x00000000d6f7a970>”，指該地址被占用了，線程在等待給這個 0x00000000d6f7a970地址上鎖。
3）在 dump 日志里查找字符串 0x00000000d6f7a970，如果發現有大量線程都在等待給這個地址上鎖。則存在問題。繼續查找字符串0x00000000d6f7a970，發現locked <0x00000000d6f7a970> (a java.lang.Integer)給地址上鎖，卻未釋放，查找該出代碼問題。
4）“waiting for monitor entry”說明此線程通過 synchronized(obj) {……} 申請進入了臨界區。
5）第一行里，"main"是 Thread Name 。tid指Java Thread id。nid指native線程的id。prio是線程優先級。[0x00000000027af000]是線程棧起始地址。

"main" #1 prio=5 os_prio=0 tid=0x000000000244e000 nid=0x2218 waiting for monitor
entry [0x00000000027af000]
java.lang.Thread.State: BLOCKED (on object monitor)
at Test.blocked(Test.java:37)
-waiting to lock <0x00000000d6f7a970> (a java.lang.Integer)
at Test.main(Test.java:16)

Locked ownable synchronizers:
-None

"Thread-0" #10 prio=5 os_prio=0 tid=0x0000000058893800 nid=0x1cc8 waiting on con
dition [0x00000000599ae000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at Test$1.run(Test.java:26)
-locked <0x00000000d6f7a970> (a java.lang.Integer)

Locked ownable synchronizers:
-None

3） 讓線程處於TIMED_WAITING狀態

public static void main(String[] args) { printPId();//打印進程id timedWaiting();//模擬TIMED_WAITING狀態方法 } public static void timedWaiting() { Integer lock = 0; synchronized (lock) { try { lock.wait(100 * 1000); } catch (Exception e) { e.printStackTrace(); } } } public static void printPId() { String name = ManagementFactory.getRuntimeMXBean().getName(); System.out.println(name.split("@")[0]); } 

根據以下輸出可以看出：
1）“TIMED_WAITING ”中的 timed_waiting 指等待狀態，但這里指定了時間，到達指定的時間后自動退出等待狀態。

"main" #1 prio=5 os_prio=0 tid=0x0000000001c1e000 nid=0x1c78 in Object.wait() [0
x000000000272f000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
-waiting on <0x00000000d6f7a970> (a java.lang.Integer)
at Test.timedWaiting(Test.java:25)
-locked <0x00000000d6f7a970> (a java.lang.Integer)
at Test.main(Test.java:18)

Locked ownable synchronizers:
-None

4） 讓線程處於WAITING狀態狀態

public static void main(String[] args) { printPId();//打印進程id waiting();//模擬waiting狀態方法 } public static void waiting() { Integer lock = 0; synchronized (lock) { try { lock.wait(); } catch (Exception e) { e.printStackTrace(); } } } public static void printPId() { String name = ManagementFactory.getRuntimeMXBean().getName(); System.out.println(name.split("@")[0]); } 

無超時的等待，必須等待lock.notify()或lock.notifyAll()或接收到interrupt信號才能退出等待狀態。同理，ReentrantLock.lock()的無參方法調用，也會使線程狀態變成WAITING。

"main" #1 prio=5 os_prio=0 tid=0x00000000024ce000 nid=0x2b14 in Object.wait() [0
x00000000025ef000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
-waiting on <0x00000000d6f7a970> (a java.lang.Integer)
at java.lang.Object.wait(Unknown Source)
at Test.waiting(Test.java:27)
-locked <0x00000000d6f7a970> (a java.lang.Integer)
at Test.main(Test.java:20)

Locked ownable synchronizers:
-None