jstack：Java堆棧跟蹤工具
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打包之后放到Linux上運行：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
|
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; @RestControllerpublic 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);} catch(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占用越來越高，系統負載也逐漸升高。
|
1
2
3
4
5
6
7
8
9
|
[root@wkp ~]# toptop - 18:13:31 up 321 days, 3:37, 4 users, load average: 13.14, 9.15, 4.72Tasks: 128 total, 1 running, 108 sleeping, 19 stopped, 0 zombieCpu(s): 99.8%us, 0.2%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%stMem: 8193352k total, 7702892k used, 490460k free, 9204k buffersSwap: 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
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
|
[root@wkp~]# top -Hp 26295top - 18:16:39 up 321 days, 3:40, 4 users, load average: 13.24, 11.14, 6.33Tasks: 31 total, 12 running, 19 sleeping, 0 stopped, 0 zombieCpu(s): 99.8%us, 0.2%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%stMem: 8193352k total, 7673852k used, 519500k free, 9752k buffersSwap: 0k total, 0k used, 0k free, 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 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 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。
|
1
2
|
[wkp@wkp4 Desktop]$ printf "%x\n" 26379670b |
然后我們通過16進制的線程號670b，在threadstack.txt文件中搜索，可以搜到對應的線程（內容太多了，只貼了一小部分）：可以看到 at com.wkp.jvm.chapter2.CpuController.loop(CpuController.java:21)，第21行就對應我們的while（true）死循環，這樣就找到了CPU飆高的原因了。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
|
2019-09-24 18:17:55Full 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文件，在文件末尾可以看到如下內容：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
|
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, a java.lang.Object), 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 deadlock. |
可以看到線程dump中已經把出現死鎖的線程打印出來了，Thread-4和Thread-5互相等待對方持有的鎖。
其實關于線程的dump和死鎖檢查等，JDK提供的有可視化的工具，比如 jconsole和jvisualvm 也是可以做到的。
另外，我們還可以通過如下 Thread.getAllStackTraces() 打印線程信息
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
|
@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 程序死鎖內容請搜索服務器之家以前的文章或繼續瀏覽下面的相關文章希望大家以后多多支持服務器之家！
原文鏈接：https://blog.csdn.net/u012988901/article/details/101039614
