Java分析系列之五：常見的Thread Dump日誌案例分析
目錄 [隱藏]
症狀及解決方案
下面列出幾種常見的症狀即對應的解決方案：
CPU佔用率很高，響應很慢
按照《Java記憶體洩漏分析系列之一：使用jstack定位執行緒堆疊資訊》中所說的方法，先找到佔用CPU的程序，然後再定位到對應的執行緒，最後分析出對應的堆疊資訊。 在同一時間多次使用上述的方法，然後進行對比分析，從程式碼中找到問題所在的原因。如果執行緒指向的是"VM Thread"或者無法從程式碼中直接找到原因，就需要進行記憶體分析，具體的見下一篇文章。
CPU佔用率不高，但響應很慢
在整個請求的過程中多次執行Thread Dump然後進行對比，取得 BLOCKED 狀態的執行緒列表，通常是因為執行緒停在了I/O、資料庫連線或網路連線的地方。
關注點概況
在Thread Dump檔案中，執行緒的狀態分成兩種：Native Thread Status和JVM Thread Status，具體的含義可以參考上一篇文章。在分析日誌的時候需要重點關注如下幾種執行緒狀態：
執行緒處於死鎖狀態，將佔用系統大量資源。
如上一篇文章中所說，系統執行緒處於這種狀態說明它在等待進入一個臨界區，此時JVM執行緒的狀態通常都是 java.lang.Thread.State: BLOCKED。
如果大量執行緒處於這種狀態的話，可能是一個全域性鎖阻塞了大量執行緒。如果短期內多次列印Thread Dump資訊，發現 waiting for monitor entry
系統執行緒處於此種狀態說明它在等待另一個條件的發生來喚醒自己，或者自己呼叫了sleep()方法。此時JVM執行緒的狀態通常是java.lang.Thread.State: WAITING (parking)（等待喚醒條件）或java.lang.Thread.State: TIMED_WAITING (parking或sleeping)（等待定時喚醒條件）。
如果大量執行緒處於此種狀態，說明這些執行緒又去獲取第三方資源了，比如第三方的網路資源或讀取資料庫的操作，長時間無法獲得響應，導致大量執行緒進入等待狀態。因此，這說明系統處於一個網路瓶頸或讀取資料庫操作時間太長。
執行緒處於阻塞狀態，需要根據實際情況進行判斷。
案例分析
下面通過幾個案例進行分解來獲得解決問題的方法。
waiting for monitor entry 和 java.lang.Thread.State: BLOCKED
"DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
- waiting to lock <0xe0375410> (a beans.ConnectionPool)
at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
"DB-Processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020]
java.lang.Thread.State: BLOCKED (on object monitor)
at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
- waiting to lock <0xe0375410> (a beans.ConnectionPool)
at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
"DB-Processor-3" daemon prio=5 tid=0x00928248 nid=0x8b waiting for monitor entry [0x000000000825d080]
java.lang.Thread.State: RUNNABLE
at oracle.jdbc.driver.OracleConnection.isClosed(OracleConnection.java:570)
- waiting to lock <0xe03ba2e0> (a oracle.jdbc.driver.OracleConnection)
at beans.ConnectionPool.getConnection(ConnectionPool.java:112)
- locked <0xe0386580> (a java.util.Vector)
- locked <0xe0375410> (a beans.ConnectionPool)
at beans.cus.Cue_1700c.GetNationList(Cue_1700c.java:66)
at org.apache.jsp.cue_1700c_jsp._jspService(cue_1700c_jsp.java:120)
上面系統執行緒的狀態是 waiting for monitor entry，說明此執行緒通過 synchronized(obj) { } 申請進入臨界區，但obj對應的 Monitor 被其他執行緒所擁有，所以 JVM執行緒的狀態是 java.lang.Thread.State: BLOCKED (on object monitor)，說明執行緒等待資源超時。
下面的 waiting to lock <0xe0375410> 說明執行緒在等待給 0xe0375410 這個地址上鎖（trying to obtain 0xe0375410 lock），如果在日誌中發現有大量的執行緒都在等待給 0xe0375410 上鎖的話，這個時候需要在日誌中查詢那個執行緒獲取了這個鎖 locked <0xe0375410>，如上面的例子中是 "DB-Processor-14" 這個執行緒，這樣就可以順藤摸瓜了。上面的例子是因為獲取資料庫操作等待的時間太長所致的，這個時候就需要修改資料庫連線的配置資訊。
如果兩個執行緒相互都被對方的執行緒鎖鎖住，這樣就造成了 死鎖 現象，如下面的例子所示：
waiting on condition 和 java.lang.Thread.State: 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)
JVM執行緒的狀態是 java.lang.Thread.State: TIMED_WAITING (parking)，說明執行緒處於定時等待的狀態，parking指執行緒處於掛起中。
waiting on condition需要結合堆疊中的 parking to wait for <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack) 一起來分析。首先，本執行緒肯定是在等待某個條件的發生來把自己喚醒。其次，SynchronousQueue並不是一個佇列，只是執行緒之間移交資訊的機制，當我們把一個元素放入到 SynchronousQueue 中的時候必須有另一個執行緒正在等待接受移交的任務，因此這就是本執行緒在等待的條件。
in Object.wait() 和 java.lang.Thread.State: 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)
本例中JVM執行緒的狀態是 java.lang.Thread.State: TIMED_WAITING (on object monitor)，說明執行緒呼叫了 java.lang.Object.wait(long timeout) 方法而進入了等待狀態。
"Wait Set"中等待的執行緒狀態就是 in Object.wait()，當執行緒獲得了 Monitor進入臨界區之後，如果發現執行緒繼續執行的條件沒有滿足，它就呼叫物件（通常是被 synchronized 的物件）的wait()方法，放棄了Monitor，進入 "Wait Set" 佇列中。只有當別的執行緒在該物件上呼叫了 notify()或notifyAll()方法， "Wait Set" 佇列中執行緒才得到機會去競爭，但是隻有一個執行緒獲得物件的 Monitor，恢復到的執行態。
另外需要注意的是，是先 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>）。
前面幾篇文章詳細說明了如何分析Thread Dump檔案，除此之外還可以通過分析JVM堆記憶體資訊來進一步找到問題的原因。