1. 程式人生 > >Java分析系列之四:jstack生成的Thread Dump日誌執行緒狀態

Java分析系列之四:jstack生成的Thread Dump日誌執行緒狀態

前面文章中只分析了Thread Dump日誌檔案的結構,今天針對日誌檔案中 Java EE middleware, third party & custom application Threads 部分執行緒的狀態進行詳細的分析。

目錄 [隱藏]

Thread Dump日誌的執行緒資訊

以下面的日誌為例:

"resin-22129" daemon prio=10 tid=0x00007fbe5c34e000 nid=0x4cb1 waiting on condition [0x00007fbe4ff7c000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:315)
    at com.caucho.env.thread2.ResinThread2.park(ResinThread2.java:196)
    at com.caucho.env.thread2.ResinThread2.runTasks(ResinThread2.java:147)
    at com.caucho.env.thread2.ResinThread2.run(ResinThread2.java:118)


"Timer-20" daemon prio=10 tid=0x00007fe3a4bfb800 nid=0x1a31 in Object.wait() [0x00007fe3a077a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006f0620ff0> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000006f0620ff0> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

以上依次是:

  • "resin-22129" 執行緒名稱:如果使用 java.lang.Thread 類生成一個執行緒的時候,執行緒名稱為 Thread-(數字) 的形式,這裡是resin生成的執行緒;
  • daemon 執行緒型別:執行緒分為守護執行緒 (daemon) 和非守護執行緒 (non-daemon) 兩種,通常都是守護執行緒;
  • prio=10 執行緒優先順序:預設為5,數字越大優先順序越高;
  • tid=0x00007fbe5c34e000 JVM執行緒的id:JVM內部執行緒的唯一標識,通過 java.lang.Thread.getId()獲取,通常用自增的方式實現;
  • nid=0x4cb1
    系統執行緒id:對應的系統執行緒id(Native Thread ID),可以通過 top 命令進行檢視,現場id是十六進位制的形式;
  • waiting on condition 系統執行緒狀態:這裡是系統的執行緒狀態,具體的含義見下面 系統執行緒狀態 部分;
  • [0x00007fbe4ff7c000] 起始棧地址:執行緒堆疊呼叫的其實記憶體地址;
  • java.lang.Thread.State: WAITING (parking) JVM執行緒狀態:這裡標明瞭執行緒在程式碼級別的狀態,詳細的內容見下面的 JVM執行緒執行狀態 部分。
  • 執行緒呼叫棧資訊:下面就是當前執行緒呼叫的詳細棧資訊,用於程式碼的分析。堆疊資訊應該從下向上解讀,因為程式呼叫的順序是從下向上的。

系統執行緒狀態 (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"和"Waint 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執行緒執行狀態 (JVM Thread Status)

java.lang.Thread.State 中定義了執行緒的狀態:

NEW

至今尚未啟動的執行緒的狀態。執行緒剛被建立,但尚未啟動。

RUNNABLE

可執行執行緒的執行緒狀態。執行緒正在JVM中執行,有可能在等待作業系統中的其他資源,比如處理器。

BLOCKED

受阻塞並且正在等待監視器的某一執行緒的執行緒狀態。處於受阻塞狀態的某一執行緒正在等待監視器鎖,以便進入一個同步的塊/方法,或者在呼叫 Object.wait 之後再次進入同步的塊/方法。
在Thread Dump日誌中通常顯示為 java.lang.Thread.State: BLOCKED (on object monitor)

WAITING

某一等待執行緒的執行緒狀態。執行緒正在無期限地等待另一個執行緒來執行某一個特定的操作,執行緒因為呼叫下面的方法之一而處於等待狀態:

  • 不帶超時的 Object.wait 方法,日誌中顯示為 java.lang.Thread.State: WAITING (on object monitor)
  • 不帶超時的 Thread.join 方法
  • LockSupport.park 方法,日誌中顯示為 java.lang.Thread.State: WAITING (parking)

TIMED_WAITING

指定了等待時間的某一等待執行緒的執行緒狀態。執行緒正在等待另一個執行緒來執行某一個特定的操作,並設定了指定等待的時間,執行緒因為呼叫下面的方法之一而處於定時等待狀態:

  • Thread.sleep 方法
  • 指定超時值的 Object.wait 方法
  • 指定超時值的 Thread.join 方法
  • LockSupport.parkNanos
  • LockSupport.parkUntil

TERMINATED

執行緒處於終止狀態。

根據Java Doc中的說明,在給定的時間上,一個只能處於上述的一種狀態之中,並且這些狀態都是JVM的狀態,跟作業系統中的執行緒狀態無關。

執行緒狀態樣例

等待狀態樣例

 "IoWaitThread" prio=6 tid=0x0000000007334800 nid=0x2b3c waiting on condition [0x000000000893f000]
   java.lang.Thread.State: WAITING (parking)
                at sun.misc.Unsafe.park(Native Method)
                - parking to wait for  <0x00000007d5c45850> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
                at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
                at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
                at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:440)
                at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:629)
                at com.nbp.theplatform.threaddump.ThreadIoWaitState$IoWaitHandler2.run(ThreadIoWaitState.java:89)
                at java.lang.Thread.run(Thread.java:662) 

上面例子中,IoWaitThread 執行緒保持等待狀態並從 LinkedBlockingQueue 接收訊息,如果 LinkedBlockingQueue 一直沒有訊息,該執行緒的狀態將不會改變。

阻塞狀態樣例

"BLOCKED_TEST pool-1-thread-1" prio=6 tid=0x0000000006904800 nid=0x28f4 runnable [0x000000000785f000]
   java.lang.Thread.State: RUNNABLE
                at java.io.FileOutputStream.writeBytes(Native Method)
                at java.io.FileOutputStream.write(FileOutputStream.java:282)
                at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
                at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
                - locked <0x0000000780a31778> (a java.io.BufferedOutputStream)
                at java.io.PrintStream.write(PrintStream.java:432)
                - locked <0x0000000780a04118> (a java.io.PrintStream)
                at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
                at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
                at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:85)
                - locked <0x0000000780a040c0> (a java.io.OutputStreamWriter)
                at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168)
                at java.io.PrintStream.newLine(PrintStream.java:496)
                - locked <0x0000000780a04118> (a java.io.PrintStream)
                at java.io.PrintStream.println(PrintStream.java:687)
                - locked <0x0000000780a04118> (a java.io.PrintStream)
                at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:44)
                - locked <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState)
                at com.nbp.theplatform.threaddump.ThreadBlockedState$1.run(ThreadBlockedState.java:7)
                at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                at java.lang.Thread.run(Thread.java:662)
   Locked ownable synchronizers:
                - <0x0000000780a31758> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
"BLOCKED_TEST pool-1-thread-2" prio=6 tid=0x0000000007673800 nid=0x260c waiting for monitor entry [0x0000000008abf000]
   java.lang.Thread.State: BLOCKED (on object monitor)
                at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:43)
                - waiting to lock <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState)
                at com.nbp.theplatform.threaddump.ThreadBlockedState$2.run(ThreadBlockedState.java:26)
                at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                at java.lang.Thread.run(Thread.java:662)
   Locked ownable synchronizers:
                - <0x0000000780b0c6a0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
"BLOCKED_TEST pool-1-thread-3" prio=6 tid=0x00000000074f5800 nid=0x1994 waiting for monitor entry [0x0000000008bbf000]
   java.lang.Thread.State: BLOCKED (on object monitor)
                at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:42)
                - waiting to lock <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState)
                at com.nbp.theplatform.threaddump.ThreadBlockedState$3.run(ThreadBlockedState.java:34)
                at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                at java.lang.Thread.run(Thread.java:662)
   Locked ownable synchronizers:
                - <0x0000000780b0e1b8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

在上面的例子中,BLOCKED_TEST pool-1-thread-1 執行緒佔用了 <0x0000000780a000b0> 鎖,然而 BLOCKED_TEST pool-1-thread-2 和 BLOCKED_TEST pool-1-thread-3 threads 正在等待獲取鎖。

死鎖狀態樣例

"DEADLOCK_TEST-1" daemon prio=6 tid=0x000000000690f800 nid=0x1820 waiting for monitor entry [0x000000000805f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197)
                - waiting to lock <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182)
                - locked <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)

   Locked ownable synchronizers:
                - None

"DEADLOCK_TEST-2" daemon prio=6 tid=0x0000000006858800 nid=0x17b8 waiting for monitor entry [0x000000000815f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197)
                - waiting to lock <0x00000007d58f5e78> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182)
                - locked <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)

   Locked ownable synchronizers:
                - None

"DEADLOCK_TEST-3" daemon prio=6 tid=0x0000000006859000 nid=0x25dc waiting for monitor entry [0x000000000825f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197)
                - waiting to lock <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182)
                - locked <0x00000007d58f5e78> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)

   Locked ownable synchronizers:
                - None

上面的例子中,當執行緒 A 需要獲取執行緒 B 的鎖來繼續它的任務,然而執行緒 B 也需要獲取執行緒 A 的鎖來繼續它的任務的時候發生的。在 thread dump 中,你能看到 DEADLOCK_TEST-1 執行緒持有 0x00000007d58f5e48 鎖,並且嘗試獲取 0x00000007d58f5e60 鎖。你也能看到 DEADLOCK_TEST-2 執行緒持有 0x00000007d58f5e60,並且嘗試獲取 0x00000007d58f5e78,同時 DEADLOCK_TEST-3 執行緒持有 0x00000007d58f5e78,並且在嘗試獲取 0x00000007d58f5e48 鎖,如你所見,每個執行緒都在等待獲取另外一個執行緒的鎖,這狀態將不會被改變直到一個執行緒丟棄了它的鎖。

無限等待的Runnable狀態樣例

"socketReadThread" prio=6 tid=0x0000000006a0d800 nid=0x1b40 runnable [0x00000000089ef000]
   java.lang.Thread.State: RUNNABLE
                at java.net.SocketInputStream.socketRead0(Native Method)
                at java.net.SocketInputStream.read(SocketInputStream.java:129)
                at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
                at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
                at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
                - locked <0x00000007d78a2230> (a java.io.InputStreamReader)
                at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:107)
                - locked <0x00000007d78a2230> (a java.io.InputStreamReader)
                at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:93)
                at java.io.InputStreamReader.read(InputStreamReader.java:151)
                at com.nbp.theplatform.threaddump.ThreadSocketReadState$1.run(ThreadSocketReadState.java:27)
                at java.lang.Thread.run(Thread.java:662)

上例中執行緒的狀態是RUNNABLE,但在下面的堆疊日誌中發現socketReadThread 執行緒正在無限等待讀取 socket,因此不能單純通過執行緒的狀態來確定執行緒是否處於阻塞狀態,應該根據詳細的堆疊資訊進行分析。

下一節將講述常見的Thread Dump日誌案例分析。

參考資料:
How to Analyze Java Thread Dumps | 中文版
三個例項演示 Java Thread Dump 日誌分析
效能分析之-- JAVA Thread Dump 分析綜述
各種 Java Thread State 第一分析法則

Related Posts:

記憶體洩漏