jstack配合top命令分析CPU飆高、程式死鎖問題
阿新 • • 發佈：2021-09-24
tack：堆疊跟蹤工具
jstack（Stack Trace for Java)命令用於生成虛擬機器當前時刻的執行緒快照（一般稱為threaddump或者javacore檔案）。執行緒快照就是當前虛擬機器內每一條執行緒正在執行的方法堆疊的集合，生成執行緒快照的主要目的是定位執行緒出現長時間停頓的原因，如執行緒間死鎖、死迴圈、請求外部資源導致的長時間等待等都是導致執行緒長時間停頓的常見原因。執行緒出現停頓的時候通過jstack來檢視各個執行緒的呼叫堆疊，就可以知道沒有響應的執行緒到底在後臺做什麼事情，或者等待什麼資源。jstack的官方文件地址為：https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jstack.html。
jstack命令格式：jstack [option] vmid
jstack的主要option選項如下：
- -F：當正常輸出的請求不被響應時，強制輸出執行緒堆疊。
- -l：除堆疊外，顯示關於鎖的附加資訊。
- -m：除列印java執行緒堆疊外，還會輸出native方法執行緒堆疊。
Java執行緒狀態轉化
官網執行緒狀態介紹：https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr034.html，如下所示
- NEW：建立了執行緒但是還沒有呼叫start方法
- RUNABLE：執行緒正在JVM中執行，有可能在等待CPU時間片輪轉
- TIMED_WAITING：執行緒等待指定的時間，一般則是處於sleep方法，wait方法，join等操作，正在等待時間
- WAITING：執行緒無限期的等待，一般是wait，join等方法沒有指定時間
- BLOCKED：執行緒等待獲取監視器鎖而處於阻塞狀態
- TERMINATED：執行緒退出
關於執行緒各個狀態的轉化，從網上找了一張圖，畫的挺詳細的。
jstack配合top命令分析CPU飆高問題
一般分析CPU飆高的步驟如下：
- 先用top 命令在機器上分析出當前佔用cpu的程序，
- 通過top -H -p <pid> 檢視程序內各個執行緒的資源佔用
- top -H -p <pid>命令輸出的是這些執行緒的pid，然後通過jstack命令匯出執行緒dump資訊。把執行緒pid（對應執行緒dump內容中的nid，nid是16進製表示的）轉換成十六進位制，然後線上程dump檔案中搜索即可找到對應的執行緒。
建立一個springboot工程，controller程式如下，然後通過package -Dmaven.test.skip=true打包之後放到上執行：
package com.wkp.jvm.chapter2;
import java.util.List;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
@RestController
public class CpuController {
Logger log=LoggerFactory.getLogger(CpuController.class);
/**
* 演示死迴圈
*/
@RequestMapping("/loop")
public List<Long> loop(){
log.info("演示死迴圈============");
while(true){
}
}
private Object lock1 = new Object();
private Object lock2 = new Object();
/**
* 演示死鎖
*/
@RequestMapping("/deadlock")
public String deadlock() {
log.info("演示死鎖============");
new Thread(()->{
synchronized(lock1) {
try {Thread.sleep(1000);} cwww.cppcns.comatch(Exception e) {}
synchronized(lock2){
System.out.println("Thread 1 over");
}
}
}).start();
new Thread(()->{
synchronized(lock2) {
try {Thread.sleep(1000);} catch(Exception e) {}
synchronized(lock1){
System.out.println("Thread 2 over");
}
}
}).start();
return "deadlock";
}
}
通過http://ip:port/loop訪問觸發程式死迴圈，多訪問幾次之後，在Linux上通過top命令可以看到我們的Java應用程式CPU佔用越來越高，系統負載也逐漸升高。
[root@wkp ~]# top top - 18:13:31 up 321 days,3:37,4 users,load average: 13.14,9.15,4.72 Tasks: 128 total,1 running,108 sleeping,19 stopped,0 zombie Cpu(s): 99.8%us,0.2%sy,0.0%ni,0.0%id,0.0%wa,0.0%hi,0.0%si,0.0%st Mem: 8193352k total,7702892k used,490460k free,9204k buffers Swap: 0k total,0k used,0k free,75428k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 26295 root 20 0 4524m 378m 13m S 184.8 4.7 13:51.51 java
通過top命令，我們觀察到java程序26295佔用CPU很高，系統負載也越來越高.然後我們通過top -Hp 26295檢視程序的執行緒佔用情況。
top -Hp pid 可以檢視某個程序的執行緒資訊，其中-H 顯示執行緒資訊，-p指定pid
[root@wkp~]#www.cppcns.com top -Hp 26295
top - 18:16:39 up 321 days,3:40,load average: 13.24,11.14,6.33
Tasks: 31 total,12 running,19 sleeping,0 stopped,7673852k used,519500k free,9752k buffers
Swap: 0k total,75508k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26379 root 20 0 4524m 378m 13m R 15.6 4.7 2:36.42 java
26384 root 20 0 4524m 378m 13m R 15.6 4.7 1:41.46 java
26388 root 20 0 4524m 378m 13m R 15.6 4.7 1:10.34 java
5673 root 20 0 4524m 378m 13m R 15.6 4.7 1:07.09 java
26386 root 20 0 4524m 378m 13m R 15.3 4.7 1:17.68 java http://www.cppcns.com
26380 root 20 0 4524m 378m 13m R 15.0 4.7 2:18.31 java
26381 root 20 0 4524m 378m 13m R 15.0 4.7 2:05.06 java
26382 root 20 0 4524m 378m 13m R 15.0 4.7 1:45.69 java
26385 root 20 0 4524m 378m 13m R 15.0 4.7 1:20.29 java
26387 root 20 0 4524m 378m 13m R 15.0 4.7 1:13.59 java
5801 root 20 0 4524m 378m 13m R 15.0 4.7 0:51.41 java
26383 root 20 0 4524m 378m 13m R 14.6 4.7 1:55.11 java
26295 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java
26305 root 20 0 4524m 378m 13m S 0.0 4.7 0:02.63 java
26306 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.21 java
26307 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.20 java http://www.cppcns.com
26311 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.36 java
26312 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java
26314 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.01 java
26327 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java
26328 root 20 0 4524m 378m 13m S 0.0 4.7 0:03.67 java
26329 root 20 0 4524m 378m 13m S 0.0 4.7 0:01.33 java
26330 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java
26331 root 20 0 4524m 378m 13m S 0.0 4.7 0:01.79 java
26376 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.06 java
26377 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java
26378 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.13 java
26389 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.13 java
26390 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.11 java
26391 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java
26392 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.16 java
然後我們執行 jstack 26295 > threadstack.txt 命令，將執行緒dump資訊輸出到txt檔案中，然後下載下來。因為jstack打印出的執行緒堆疊中執行緒號是16進位制的，所以我們從上面top -Hp命令打印出的執行緒中選取第一個26379，通過 printf "%x\n" 26379轉為16進製得到670b。
[wkp@wkp4 Desktop]$ printf "%x\n" 26379 670b
然後我們通過16進位制的執行緒號670b，在threadstack.txt檔案中搜索，可以搜到對應的執行緒（內容太多了，只貼了一小部分）：可以看到 at com.wkp.jvm.chapter2.CpuController.loop(CpuController.java:21)，第21行就對應我們的while（true）死迴圈，這樣就找到了CPU飆高的原因了。
2019-09-24 18:17:55 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.162-b12 mixed mode): //=========省略=============================================== "http-nio-9999-exec-1" #16 daemon prio=5 os_prio=0 tid=0x00007fa06943c800 nid=0x670b runnable [0x00007fa01b3e9000] java.lang.Thread.State: RUNNABLE at com.wkp.jvm.chapter2.CpuController.loop(CpuController.java:21) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) //=========省略=============================================== "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fa06813e000 nid=0x66d9 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fa06813b000 nid=0x66d8 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fa068106800 nid=0x66ca in Object.wait() [0x00007fa054267000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000082ebc820> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143) - locked <0x0000000082ebc820> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212) "VM Thread" os_prio=0 tid=0x00007fa0680fa000 nid=0x66c7 runnable "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fa06801e000 nid=0x66c2 runnable "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fa068020000 nid=0x66c3 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007fa068146000 nid=0x66db waiting on condition JNI global references: 913
下面我們對執行緒dump日誌的格式做個介紹，以 "http-nio-9999-exec-1" #16 daemon prio=5 os_prio=0 tid=0x00007fa06943c800 nid=0x670b runnable [0x00007fa01b3e9000]為例：
- http-nio-9999-exec-1：執行緒名稱
- daemon執行緒型別：執行緒分為守護執行緒 (daemon) 和非守護執行緒 (non-daemon) 兩種，通常都是守護執行緒
- prio=5：執行緒優先順序：預設為5，數字越大優先順序越高
- tid=0x00007fa06943c800JVM執行緒的id：JVM內部執行緒的唯一標識，通過 java.lang.Thread.getId()獲取，通常用自增的方式實現；
- nid=0x670b系統執行緒id：對應的系統執行緒id（Native Thread ID)，可以通過 top -Hp命令進行檢視，執行緒id是十六進位制的形式
- runnable：系統執行緒的狀態
- [0x00007fa01b3e9000]起始棧地址：執行緒堆疊呼叫的起始記憶體地址
其他的執行緒名含義：
- "C1 CompilerThread1"和"C1 CompilerThread0"是Java的編譯執行緒
- "Finalizer"是垃圾回收時，被標記的物件被放到F-Queue佇列中，Finalizer執行緒取出佇列中的物件進行處理
- "GC task thread#0 (ParallelGC)" 和"GC task thread#1 (ParallelGC)" 是ParallelGC垃圾收集器的工作執行緒
jstack配合top命令查詢死鎖
我們演示一下死鎖問題的查詢：同樣是啟動上面的示例springboot程式，然後訪問 http://ip:port/deadlock觸發程式死鎖。然後通過jstack匯出執行緒dump檔案，在檔案末尾可以看到如下內容：
Found one Java-level deadlock: ============================= "Thread-5": waiting to lock monitor 0x00007fc978003778 (object 0x00000000833d0c20,a java.lang.Object),which is held by "Thread-4" "Thread-4": waiting to lock monitor 0x00007fc978003568 (object 0x00000000833d0c30,which is held by "Thread-5" Java stack information for the threads listed above: =================================================== "Thread-5": at com.wkp.jvm.chapter2.CpuController.lambda$deadlock$1(CpuController.java:46) - waiting to lock <0x00000000833d0c20> (a java.lang.Object) - locked <0x00000000833d0c30> (a java.lang.Object) at com.wkp.jvm.chapter2.CpuController$$Lambda$343/408916933.run(Unknown Source) at java.lang.Thread.run(Thread.java:748) "Thread-4": at com.wkp.jvm.chapter2.CpuController.lambda$deadlock$0(CpuController.java:38) - waiting to lock <0x00000000833d0c30> (a java.lang.Object) - locked <0x00000000833d0c20> (a java.lang.Object) at com.wkp.jvm.chapter2.CpuController$$Lambda$342/620117450.run(Unknown Source) at java.lang.Thread.run(Thread.java:748) Found 1 deadloiaMSanIck.
可以看到執行緒dump中已經把出現死鎖的執行緒打印出來了，Thread-4和Thread-5互相等待對方持有的鎖。
其實關於執行緒的dump和死鎖檢查等，JDK提供的有視覺化的工具，比如 jconsole和jvisualvm 也是可以做到的。
另外，我們還可以通過如下 Thread.getAllStackTraces() 列印執行緒資訊
@RequestMapping("/getAllThreadStack")
public void getAllThreadStack() {
for (Entry<Thread,StackTraceElement[]> stackTrace : Thread
.getAllStackTraces().entrySet()) {
Thread thread = (Thread) stackTrace.getKey();
StackTraceElement[] stack = (StackTraceElement[]) stackTrace
.getValue();
if (thread.equals(Thread.currentThread())) {
continue;
}
System.out.println("執行緒：" + thread.getName());
for (StackTraceElement stackTraceElement : stack) {
System.out.println(stackTraceElement);
}
}
}
到此這篇關於jstack配合top命令分析CPU飆高、程式死鎖問題的文章就介紹到這了,更多相關Java 程式死鎖內容請搜尋我們以前的文章或繼續瀏覽下面的相關文章希望大家以後多多支援我們！