Thread Dump線程死結偵查工具（JStack）的使用詳解

Thread Dump用來診斷Java應用的問題，可以用來發現死結線程等等。通過它可以得到線程，線程運行狀態、標識、調用的堆棧，堆棧包含完整的類名，所執行的方法，以及原始碼所在的行數等等資訊。

接下來，需要考慮如何獲得Thread Dump的問題。首先，可以通過jps查看java的進程資訊，從而獲得java進程的進程號。也可以用top動態觀察CPU使用情況分析進程情況。然後通過jdk內建的工具jstack進行分析。jstack <pid> >> filename 可以將pid對應的java進程的線程使用方式寫到後面的file中去。

如下列代碼：

/** * 死結例子 * @author crane.ding * @since 2011-3-20 */public class DeadLock {public static void main(String[] args) {final Object obj_1 = new Object(), obj_2 = new Object();Thread t1 = new Thread("t1"){@Overridepublic void run() {synchronized (obj_1) {try {Thread.sleep(3000);} catch (InterruptedException e) {}synchronized (obj_2) {System.out.println("thread t1 done.");}}}};Thread t2 = new Thread("t2"){@Overridepublic void run() {synchronized (obj_2) {try {Thread.sleep(3000);} catch (InterruptedException e) {}synchronized (obj_1) {System.out.println("thread t2 done.");}}}};t1.start();t2.start();}}

通過以上的工具使用完畢後可以得到Thread Dump的快照

2011-03-20 23:05:20Full thread dump Java HotSpot(TM) Client VM (19.1-b02 mixed mode, sharing):"DestroyJavaVM" prio=6 tid=0x00316800 nid=0x9fc waiting on condition [0x00000000]   java.lang.Thread.State: RUNNABLE   Locked ownable synchronizers:- None"t2" prio=6 tid=0x02bcf000 nid=0xc70 waiting for monitor entry [0x02f6f000]   java.lang.Thread.State: BLOCKED (on object monitor)at com.demo.DeadLock$2.run(DeadLock.java:40)- waiting to lock <0x22a297a8> (a java.lang.Object)- locked <0x22a297b0> (a java.lang.Object)   Locked ownable synchronizers:- None"t1" prio=6 tid=0x02bce400 nid=0xba0 waiting for monitor entry [0x02f1f000]   java.lang.Thread.State: BLOCKED (on object monitor)at com.demo.DeadLock$1.run(DeadLock.java:25)- waiting to lock <0x22a297b0> (a java.lang.Object)- locked <0x22a297a8> (a java.lang.Object)   Locked ownable synchronizers:- None"Low Memory Detector" daemon prio=6 tid=0x02bb9400 nid=0xa6c runnable [0x00000000]   java.lang.Thread.State: RUNNABLE   Locked ownable synchronizers:- None"CompilerThread0" daemon prio=10 tid=0x02bb2800 nid=0xcb8 waiting on condition [0x00000000]   java.lang.Thread.State: RUNNABLE   Locked ownable synchronizers:- None"Attach Listener" daemon prio=10 tid=0x02bb1000 nid=0x7f4 waiting on condition [0x00000000]   java.lang.Thread.State: RUNNABLE   Locked ownable synchronizers:- None"Signal Dispatcher" daemon prio=10 tid=0x02bd2800 nid=0xd80 runnable [0x00000000]   java.lang.Thread.State: RUNNABLE   Locked ownable synchronizers:- None"Finalizer" daemon prio=8 tid=0x02bab000 nid=0xe1c in Object.wait() [0x02d3f000]   java.lang.Thread.State: WAITING (on object monitor)at java.lang.Object.wait(Native Method)- waiting on <0x229e1148> (a java.lang.ref.ReferenceQueue$Lock)at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)- locked <0x229e1148> (a java.lang.ref.ReferenceQueue$Lock)at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)   Locked ownable synchronizers:- None"Reference Handler" daemon prio=10 tid=0x02ba6800 nid=0xbe0 in Object.wait() [0x02cef000]   java.lang.Thread.State: WAITING (on object monitor)at java.lang.Object.wait(Native Method)- waiting on <0x229e1048> (a java.lang.ref.Reference$Lock)at java.lang.Object.wait(Object.java:485)at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)- locked <0x229e1048> (a java.lang.ref.Reference$Lock)   Locked ownable synchronizers:- None"VM Thread" prio=10 tid=0x02b6a400 nid=0x568 runnable "VM Periodic Task Thread" prio=10 tid=0x02bc8400 nid=0x75c waiting on condition JNI global references: 878Found one Java-level deadlock:============================="t2":  waiting to lock monitor 0x02baaeec (object 0x22a297a8, a java.lang.Object),  which is held by "t1""t1":  waiting to lock monitor 0x02baa2bc (object 0x22a297b0, a java.lang.Object),  which is held by "t2"Java stack information for the threads listed above:==================================================="t2":at com.demo.DeadLock$2.run(DeadLock.java:40)- waiting to lock <0x22a297a8> (a java.lang.Object)- locked <0x22a297b0> (a java.lang.Object)"t1":at com.demo.DeadLock$1.run(DeadLock.java:25)- waiting to lock <0x22a297b0> (a java.lang.Object)- locked <0x22a297a8> (a java.lang.Object)Found 1 deadlock.

jstack Dump 記錄檔中的線程狀態 dump 檔案裡，值得關注的線程狀態有： 死結，Deadlock（重點關注）  執行中，Runnable    等待資源，Waiting on condition（重點關注）  等待擷取監視器，Waiting on monitor entry（重點關注） 暫停，Suspended 對象等待中，Object.wait() 或 TIMED_WAITING 阻塞，Blocked（重點關注）   停止，Parked 綜合示範一：Waiting to lock 和 Blocked 執行個體如下： "RMI TCP Connection(267865)-172.16.5.25" daemon prio=10 tid=0x00007fd508371000 nid=0x55ae  waiting for monitor entry  [ 0x00007fd4f8684000 ]    java.lang.Thread.State:  BLOCKED (on object monitor) at org.apache.log4j.Category.callAppenders(Category.java:201) -  waiting to lock <0x00000000acf4d0c0>  (a org.apache.log4j.Logger) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.log(Category.java:853) at org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:234) at com.tuan.core.common.lang.cache.remote.SpyMemcachedClient.get(SpyMemcachedClient.java:110) …… 1）線程狀態是  Blocked，阻塞狀態。說明線程等待資源逾時。 2）“  waiting to lock <0x00000000acf4d0c0>”指，線程在等待給這個 0x00000000acf4d0c0 地址上鎖（英文可描述為：trying to obtain  0x00000000acf4d0c0 lock）。 3）在 dump 日誌裡尋找字串 0x00000000acf4d0c0，發現 有大量線程都在等待給這個地址上鎖。如果能在日誌裡找到誰獲得了這個鎖（如locked < 0x00000000acf4d0c0 >），就可以順藤摸瓜了。 4）“ waiting for monitor entry”說明此線程通過 synchronized(obj) {……} 申請進入了臨界區，從而進入了下圖1中的“Entry Set”隊列，但該 obj 對應的 monitor 被其他線程擁有，所以本線程在 Entry Set 隊列中等待。 5）第一行裡， "RMI TCP Connection(267865)-172.16.5.25"是 Thread Name 。tid指Java Thread id。nid指native線程的id。prio是線程優先順序。 [ 0x00007fd4f8684000 ]是線程棧起始地址。   Dump檔案中的線程狀態含義及注意事項

含義如下所示： Deadlock：死結線程，一般指多個線程調用間，進入相互資源佔用，導致一直等待無法釋放的情況。 Runnable：一般指該線程正在執行狀態中，該線程佔用了資源，正在處理某個請求，有可能正在傳遞SQL到資料庫執行，有可能在對某個檔案操作，有可能進行資料類型等轉換。 Waiting on condition：等待資源，或等待某個條件的發生。具體原因需結合 stacktrace來分析。 如果堆棧資訊明確是應用代碼，則證明該線程正在等待資源。一般是大量讀取某資源，且該資源採用了資源鎖的情況下，線程進入等待狀態，等待資源的讀取。 又或者，正在等待其他線程的執行等。 如果發現有大量的線程都在處在 Wait on condition，從線程 stack看，正等待網路讀寫，這可能是一個網路瓶頸的徵兆。因為網路阻塞導致線程無法執行。 一種情況是網路非常忙，幾乎消耗了所有的頻寬，仍然有大量資料等待網路讀寫； 另一種情況也可能是網路空閑，但由於路由等問題，導致包無法正常的到達。 另外一種出現 Wait on condition的常見情況是該線程在 sleep，等待 sleep的時間到了時候，將被喚醒。 Blocked：線程阻塞，是指當前線程執行過程中，所需要的資源長時間等待卻一直未能擷取到，被容器的線程管理器標識為阻塞狀態，可以理解為等待資源逾時的線程。 Waiting for monitor entry 和 in Object.wait()：Monitor是 Java中用以實現線程之間的互斥與協作的主要手段，它可以看成是對象或者 Class的鎖。每一個對象都有，也僅有一個 monitor。從下圖1中可以看出，每個 Monitor在某個時刻，只能被一個線程擁有，該線程就是 “Active Thread”，而其它線程都是 “Waiting Thread”，分別在兩個隊列 “ Entry Set”和 “Wait Set”裡面等候。在 “Entry Set”中等待的線程狀態是 “Waiting for monitor entry”，而在 “Wait Set”中等待的線程狀態是 “in Object.wait()”。

圖1 A Java Monitor

  綜合示範二：W aiting on condition  和 TIMED_WAITING 執行個體如下： "RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fd50834e800 nid=0x56b2  waiting on condition  [0x00007fd4f1a59000]    java.lang.Thread.State:  TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) -  parking to wait for  <0x00000000acd84de8>  (a java.util.concurrent.SynchronousQueue$TransferStack) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323) at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) 1）“ TIMED_WAITING (parking)”中的 timed_waiting 指等待狀態，但這裡指定了時間，到達指定的時間後自動結束等待狀態；parking指線程處於掛起中。
2）“ waiting on condition”需要與堆棧中的“ parking to wait for  <0x00000000acd84de8>  (a java.util.concurrent.SynchronousQueue$TransferStack)”結合來看。首先，本線程肯定是在等待某個條件的發生，來把自己喚醒。其次，SynchronousQueue 並不是一個隊列，只是線程之間移交資訊的機制，當我們把一個元素放入到 SynchronousQueue 中時必須有另一個線程正在等待接受移交的任務，因此這就是本線程在等待的條件。 3）別的就看不出來了。

綜合示範三：in Obejct.wait() 和 TIMED_WAITING 執行個體如下： " RMI RenewClean-[172.16.5.19:28475] " daemon prio=10 tid=0x0000000041428800 nid=0xb09  in Object.wait()  [0x00007f34f4bd0000]    java.lang.Thread.State:  TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) -  waiting on <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) -  locked <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock) at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516) at java.lang.Thread.run(Thread.java:662) 1）“ TIMED_WAITING (on object monitor)”，對於本例而言，是因為本線程調用了 java.lang.Object.wait(long timeout) 而進入等待狀態。

2）“Wait Set”中等待的線程狀態就是“  in Object.wait() ”。當線程獲得了 Monitor，進入了臨界區之後，如果發現線程繼續啟動並執行條件沒有滿足，它則調用對象（一般就是被 synchronized 的對象）的 wait() 方法，放棄了 Monitor，進入 “Wait Set”隊列。只有當別的線程在該對象上調用了 notify() 或者 notifyAll() ，“ Wait Set”隊列中線程才得到機會去競爭，但是只有一個線程獲得對象的 Monitor，恢複到運行態。 

3）RMI RenewClean 是 DGCClient 的一部分。 DGC 指的是 Distributed GC，即分布式記憶體回收。

4）請注意，是先  locked <0x00000000aa672478>，後  waiting on <0x00000000aa672478>，之所以先鎖再等同一個對象，請看下面它的代碼實現： static private class  Lock { }; private Lock lock = new Lock(); public Reference<? extends T>  remove(long timeout) {     synchronized (lock) {         Reference<?  extends T>  r =  reallyPoll();          if ( r !=  null)  return  r;          for (;;) {