三個實例演示 Java Thread Dump 日誌分析

jstack Dump 日誌文件中的線程狀態

dump 文件裏，值得關注的線程狀態有：

1. 死鎖，Deadlock（重點關注） 
2. 執行中，Runnable   
3. 等待資源，Waiting on condition（重點關注） 
4. 等待獲取監視器，Waiting on monitor entry（重點關注）
5. 暫停，Suspended
6. 對象等待中，Object.wait() 或 TIMED_WAITING
7. 阻塞，Blocked（重點關注）  
8. 中止，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 (;;) {

             lock.wait(timeout);

             r =  reallyPoll();

            ……

       }

}

即，線程的執行中，先用 synchronized 得到了這個對象的 Monitor（對應於    locked <0x00000000aa672478> ）；當執行到 lock.wait(timeout);，線程就放棄了 Monitor 的全部權，進入「Wait Set」隊列（對應於    waiting on <0x00000000aa672478> ）。

5）從堆棧信息看，是正在清理 remote references to remote objects ，引用的租約到了，分佈式垃圾回收在逐一清理呢。

 

參考資源：

1）CUBRID，2012， How to Analyze Java Thread Dumps；

2）iteye，2012， 虛擬機stack全分析；

3）iteye，2008， 如何分析Java虛擬機死鎖；

4）csdn，2012， java stack dump中JVM運行過程當中產生的一些常見線程介紹和解釋；

5）2009， Java線程dump的分析；

6）jiacheo，2012， tomcat thread dump 分析；

spymemcached 相關文章：

1） spymemcached 的 useNagle 問題與 TCP/IP延遲發送數據

2） spymemcached ：某個mc節點操做連續超時超過998次就 Auto-Reconnect 的特性

3） 關於 Multiget hole：spymemcached對此的實現方法

1） 55最佳實踐系列：MongoDB最佳實踐  (2012-12-15 15:48)
2） 55最佳實踐系列：Logging最佳實踐  (2012-12-15 16:43)

3） 最佳實踐系列：前端代碼標準和最佳實踐  (2012-12-19 23:33)

贈圖一枚：