Thread Dump介紹
Thread Dump是非常有用的診斷JAVA應用問題的工具。每一個Java虛擬機都有及時生成所有線程在某一點狀態的thread-dump的能力,雖然各個 Java虛擬機打印的thread dump略有不同,但是大多都提供了每個線程的所有信息,例如: 線程狀態、線程 Id、本機 Id、線程名稱、堆棧跟蹤、優先級。
Thread Dump特點
-
能在各種操作系統下使用
-
能在各種Java應用服務器下使用
-
可以在生產環境下使用而不影響系統的性能
-
可以將問題直接定位到應用程序的代碼行上(對于線上排查問題非常有用)
它能幫我們解決哪些線上問題?
Thread dump 能幫我們定位到 例如 CPU 峰值、應用程序中的無響應性、響應時間差、線程掛起、高內存消耗。
如何抓取Thread Dump
一般當服務器掛起,崩潰或者性能底下時,就需要抓取服務器的線程堆棧(Thread Dump)用于后續的分析. 在實際運行中,往往一次 dump的信息,還不足以確認問題。為了反映線程狀態的動態變化,需要接連多次做threaddump,每次間隔10-20s,建議至少產生三次 dump信息,如果每次 dump都指向同一個問題,我們才確定問題的典型性。
獲取thread dump
JDK自帶命令行工具獲取PID,再獲取ThreadDump:
1. jps 或 ps –ef|grep java (獲取PID)
2. jstack [-l ]<pid> | tee -a jstack.log (獲取ThreadDump)
實操演練
獲取所有線程的thread dump 分兩步.
- 第一步 獲取進程的PID
使用Jps 獲取所有java進程的信息
- 第二步 選取對應的pid 例如上圖紅框中的數字串 使用Jstack獲取所有線程棧信息
jstack -l 9468 | tee -a jstack.log
日志字段分析
我們把Thread dump文件分為2個部分來理解
拿我們的例子來說:
//頭部信息 包含 當前時間 jvm信息
2021-01-14 17:00:51
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):
//線程info信息塊
"ajp-nio-8019-exec-7" #75 daemon prio=5 os_prio=0 tid=0x00007fa0cc37e800 nid=0x2af3 waiting on condition [0x00007fa02eceb000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000f183aa30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.Apache.Tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrAppingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
線程info信息塊各個參數的意義:
-
線程名稱:ajp-nio-8019-exec-7
-
線程類型:daemon
-
優先級: 默認是5
-
jvm線程id:tid=0x00007fa0cc37e800,jvm內部線程的唯一標識(通過java.lang.Thread.getId()獲取,通常用自增方式實現。)
-
對應系統線程id(NativeThread ID):nid=0x2af3,和top命令查看的線程pid對應,不過一個是10進制,一個是16進制。(通過命令:top -H -p pid,可以查看該進程的所有線程信息)
-
線程狀態:java.lang.Thread.State: WAITING (parking)
-
線程調用棧信息:用于代碼的分析。堆棧信息應該從下向上解讀,因為程序調用的順序是從下向上的。
系統線程狀態 (Native Thread Status)
系統線程有如下狀態:
-
deadlock死鎖線程,一般指多個線程調用期間進入了相互資源占用,導致一直等待無法釋放的情況。
-
runnable一般指該線程正在執行狀態中,該線程占用了資源,正在處理某個操作,如通過SQL語句查詢數據庫、對某個文件進行寫入等。
-
blocked線程正處于阻塞狀態,指當前線程執行過程中,所需要的資源長時間等待卻一直未能獲取到,被容器的線程管理器標識為阻塞狀態,可以理解為等待資源超時的線程。
-
waiting on condition線程正處于等待資源或等待某個條件的發生,具體的原因需要結合下面堆棧信息進行分析。
(1)如果堆棧信息明確是應用代碼,則證明該線程正在等待資源,一般是大量讀取某種資源且該資源采用了資源鎖的情況下,線程進入等待狀態,等待資源的讀取,或者正在等待其他線程的執行等。
(2)如果發現有大量的線程都正處于這種狀態,并且堆棧信息中得知正等待網絡讀寫,這是因為網絡阻塞導致線程無法執行,很有可能是一個網絡瓶頸的征兆:
網絡非常繁忙,幾乎消耗了所有的帶寬,仍然有大量數據等待網絡讀寫;網絡可能是空閑的,但由于路由或防火墻等原因,導致包無法正常到達;所以一定要結合系統的一些性能觀察工具進行綜合分析,比如netstat統計單位時間的發送包的數量,看是否很明顯超過了所在網絡帶寬的限制;觀察CPU的利用率,看系統態的CPU時間是否明顯大于用戶態的CPU時間。這些都指向由于網絡帶寬所限導致的網絡瓶頸。
(3)還有一種常見的情況是該線程在 sleep,等待 sleep 的時間到了,將被喚醒。
- waiting for monitor entry 或 in Object.wait()Moniter 是Java中用以實現線程之間的互斥與協作的主要手段,它可以看成是對象或者class的鎖,每個對象都有,也僅有一個 Monitor。
從上圖可以看出,每個Monitor在某個時刻只能被一個線程擁有,該線程就是 "Active Thread",而其他線程都是 "Waiting Thread",分別在兩個隊列 "Entry Set"和"Wait Set"里面等待。其中在 "Entry Set" 中等待的線程狀態是 waiting for monitor entry,在 "Wait Set" 中等待的線程狀態是 in Object.wait()。
(1)"Entry Set"里面的線程。我們稱被 synchronized 保護起來的代碼段為臨界區,對應的代碼如下:
synchronized(obj) {
}
當一個線程申請進入臨界區時,它就進入了 "Entry Set" 隊列中,這時候有兩種可能性:
- 該Monitor不被其他線程擁有,"Entry Set"里面也沒有其他等待的線程。本線程即成為相應類或者對象的Monitor的Owner,執行臨界區里面的代碼;此時在Thread Dump中顯示線程處于 "Runnable" 狀態。
- 該Monitor被其他線程擁有,本線程在 "Entry Set" 隊列中等待。此時在Thread Dump中顯示線程處于 "waiting for monity entry" 狀態。臨界區的設置是為了保證其內部的代碼執行的原子性和完整性,但因為臨界區在任何時間只允許線程串行通過,這和我們使用多線程的初衷是相反的。如果在多線程程序中大量使用synchronized,或者不適當的使用它,會造成大量線程在臨界區的入口等待,造成系統的性能大幅下降。如果在Thread Dump中發現這個情況,應該審視源碼并對其進行改進。
(2)"Wait Set"里面的線程當線程獲得了Monitor,進入了臨界區之后,如果發現線程繼續運行的條件沒有滿足,它則調用對象(通常是被synchronized的對象)的wait()方法,放棄Monitor,進入 "Wait Set"隊列。只有當別的線程在該對象上調用了 notify()或者notifyAll()方法,"Wait Set"隊列中的線程才得到機會去競爭,但是只有一個線程獲得對象的Monitor,恢復到運行態。"Wait Set"中的線程在Thread Dump中顯示的狀態為 in Object.wait()。
通常來說,當CPU很忙的時候關注 Runnable 狀態的線程,反之則關注 waiting for monitor entry 狀態的線程。
JVM線程狀態
NEW:每一個線程,在堆內存中都有一個對應的Thread對象。 Thread t = new Thread();當剛剛在堆內存中創建Thread對象,還沒有調用t.start()方法之前,線程就處在NEW狀態。在這個狀態上,線程與普通的java對象沒有什么區別,就僅僅是一個堆內存中的對象。
RUNNABLE:該狀態表示線程具備所有運行條件,在運行隊列中準備操作系統的調度,或者正在運行。 這個狀態的線程比較正常,但如果線程長時間停留在在這個狀態就不正常了,這說明線程運行的時間很長(存在性能問題),或者是線程一直得不得執行的機會(存在線程饑餓的問題)。
BLOCKED:線程正在等待獲取java對象的監視器(也叫內置鎖),即線程正在等待進入由synchronized保護的方法或者代碼塊。 synchronized用來保證原子性,任意時刻最多只能由一個線程進入該臨界區域,其他線程只能排隊等待。
WAITING:處在該線程的狀態,正在等待某個事件的發生,只有特定的條件滿足,才能獲得執行機會。而產生這個特定的事件,通常都是另一個線程。也就是說,如果不發生特定的事件,那么處在該狀態的線程一直等待,不能獲取執行的機會。 比如:A線程調用了obj對象的obj.wait()方法,如果沒有線程調用obj.notify或obj.notifyAll,那么A線程就沒有辦法恢復運行;如果A線程調用了LockSupport.park(),沒有別的線程調用LockSupport.unpark(A),那么A沒有辦法恢復運行。
TIMED_WAITING:J.U.C中很多與線程相關類,都提供了限時版本和不限時版本的API。TIMED_WAITING意味著線程調用了限時版本的API,正在等待時間流逝。 當等待時間過去后,線程一樣可以恢復運行。如果線程進入了WAITING狀態,一定要特定的事件發生才能恢復運行;而處在TIMED_WAITING的線程,如果特定的事件發生或者是時間流逝完畢,都會恢復運行。
TERMINATED:線程執行完畢,執行完run方法正常返回,或者拋出了運行時異常而結束,線程都會停留在這個狀態。 這個時候線程只剩下Thread對象了,沒有什么用了。
根據dump日志分析
下面我們根據實際的代碼 來分析dump日志,可以更加透明的了解線程為什么是這個狀態
例子1:
等待釋放鎖
package jstack;
public class BlockedState
{
private static Object object = new Object();
public static void main(String[] args)
{
Runnable task = new Runnable() {
@Override
public void run()
{
synchronized (object)
{
long begin = System.currentTimeMillis();
long end = System.currentTimeMillis();
// 讓線程運行5分鐘,會一直持有object的監視器
while ((end - begin) <= 5 * 60 * 1000)
{
}
}
}
};
new Thread(task, "t1").start();
new Thread(task, "t2").start();
}
}
先獲取object的線程會執行5分鐘,這5分鐘內會一直持有object的監視器,另一個線程無法執行處在BLOCKED狀態
"t2" prio=6 tid=0x27d7a800 nid=0x1350 waiting for monitor entry [0x2833f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at jstack.BlockedState$1.run(BlockedState.java:17)
- waiting to lock <0x1cfcdc00> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:662)
"t1" prio=6 tid=0x27d79400 nid=0x1338 runnable [0x282ef000]
java.lang.Thread.State: RUNNABLE
at jstack.BlockedState$1.run(BlockedState.java:22)
- locked <0x1cfcdc00> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:662)
通過thread dump可以看到:t2線程在BLOCKED (on object monitor)。waiting for monitor entry 等待進入synchronized保護的區域 ,但obj對應的 Monitor 被其他線程所擁有,所以 JVM線程的狀態是 java.lang.Thread.State: BLOCKED (on object monitor),說明線程等待資源。
例子2:
死鎖
public class DeadLock {
public static void main(String[] args) {
final Object resource1 = "resource1";
final Object resource2 = "resource2";
Thread t1 = new Thread(){
public void run(){
synchronized(resource1){
System.out.println("Thread1:locked resource1");
try{
Thread.sleep(50);
}catch(Exception ex){
}
synchronized(resource2){
System.out.println("Thread1:locked resource2");
}
}
}
};
Thread t2 = new Thread(){
public void run(){
synchronized(resource2){
System.out.println("Thread2:locked resource2");
try{
Thread.sleep(50);
}catch(Exception ex){
}
synchronized(resource1){
System.out.println("Thread2:locked resource1");
}
}
}
};
t1.start();
t2.start();
}
}
我們的這段代碼是讓兩個線程互相等待對象釋放鎖,造成死鎖的情況,在這種情況下,獲取Thread dump文件 我們會發現jvm已經提示我們死鎖了 如下:
"Thread-1" #20 prio=5 os_prio=31 tid=0x00007fb76c0e1800 nid=0x9d03 waiting for monitor entry [0x0000700004dbf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at DeadLock$2.run(DeadLock.java:35)
- waiting to lock <0x000000076af61870> (a java.lang.String)
- locked <0x000000076af618b0> (a java.lang.String)
"Thread-0" #19 prio=5 os_prio=31 tid=0x00007fb76c002800 nid=0x9e03 waiting for monitor entry [0x0000700004cbc000]
java.lang.Thread.State: BLOCKED (on object monitor)
at DeadLock$1.run(DeadLock.java:19)
- waiting to lock <0x000000076af618b0> (a java.lang.String)
- locked <0x000000076af61870> (a java.lang.String)
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x00007fb769825b58 (object 0x000000076af61870, a java.lang.String),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x00007fb769823168 (object 0x000000076af618b0, a java.lang.String),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at DeadLock$2.run(DeadLock.java:35)
- waiting to lock <0x000000076af61870> (a java.lang.String)
- locked <0x000000076af618b0> (a java.lang.String)
"Thread-0":
at DeadLock$1.run(DeadLock.java:19)
- waiting to lock <0x000000076af618b0> (a java.lang.String)
- locked <0x000000076af61870> (a java.lang.String)
Found 1 deadlock.
例子3
調用wait(),sleep()對應的線程狀態
public static void main(String[] args) {
Thread thread = new Thread("線程1") {
//重寫run方法
public void run() {
synchronized (this) {
System.out.println(Thread.currentThread().getName());
try {
wait();
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
};
thread.start();
try {
TimeUnit.SECONDS.sleep(3);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (thread) {
System.out.println(Thread.currentThread().getName());
try {
TimeUnit.SECONDS.sleep(60);
} catch (InterruptedException e) {
e.printStackTrace();
}
thread.notify();
}
}
上面代碼會先執行線程1 run()方法,然后調用wait()方法阻塞block住。等到主線程調用thread.notify()方法之后才會繼續往下執行。我們在程序跑起來之后大概10秒時候導出thread dump日志文件信息,此時:
"線程1" #12 prio=5 os_prio=0 tid=0x00007f420024d800 nid=0x1ca5 in Object.wait() [0x00007f41e71ee000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
at java.lang.Object.wait(Object.java:502)
at com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1.run(ObjectWaitingMock.java:15)
- locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
Locked ownable synchronizers:
- None
....(其他信息這里我們省略掉)
"main" #1 prio=5 os_prio=0 tid=0x00007f420000d800 nid=0x1c84 waiting on condition [0x00007f4209891000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at com.jvm.study.threaddump.deadlock.ObjectWaitingMock.main(ObjectWaitingMock.java:31)
- locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
Locked ownable synchronizers:
- None
- [線程1]線程:wait()方法阻塞住了,狀態對應in Object.wait(),狀態詳細信息對應java.lang.Thread.State: WAITING (on object monitor)。
- [main]線程:TimeUnit.SECONDS.sleep(60)阻塞住了,狀態對應waiting on condition,狀態詳細信息對應java.lang.Thread.State: TIMED_WAITING (sleeping)。
根據案例癥狀分析解決方案
- 1 CPU占用率不高,但響應很慢
在整個請求的過程中多次執行Thread Dump然后進行對比,取得 BLOCKED狀態的線程列表,通常是因為線程停在了I/O、數據庫連接或網絡連接的地方。
- 2 CPU飆高,load高,響應很慢
一個請求過程中多次dump;對比多次dump文件的runnable線程,如果執行的方法有比較大變化,說明比較正常。如果在執行同一個方法,就有一些問題了;先找到占用CPU的進程,然后再定位到對應的線程,最后分析出對應的堆棧信息。在同一時間多次使用上述的方法,然后進行對比分析,從代碼中找到問題所在的原因.
- 3 請求無法響應
多次dump,檢查是否有 Found one Java-level deadlock提示,死鎖經常表現為程序的停頓,或者不再響應用戶的請求。從操作系統上觀察,對應進程的CPU占用率為零,很快會從top或prstat的輸出中消失。