Java內存泄漏分析系列之四：jstack生成的Thread Dump日志線程狀態

原文地址：http://www.javatang.com

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日志案例分析。