Java內存泄漏分析系列之五：常見的Thread Dump日誌案例分析

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

症狀及解決方案

下面列出幾種常見的症狀即對應的解決方案：

CPU佔用率很高，響應很慢

按照《Java內存泄漏分析系列之一：使用jstack定位線程堆棧信息》中所說的方法，先找到佔用CPU的進程，而後再定位到對應的線程，最後分析出對應的堆棧信息。
在同一時間屢次使用上述的方法，而後進行對比分析，從代碼中找到問題所在的緣由。若是線程指向的是"VM Thread"或者沒法從代碼中直接找到緣由，就須要進行內存分析，具體的見下一篇文章。

CPU佔用率不高，但響應很慢

在整個請求的過程當中屢次執行Thread Dump而後進行對比，取得 BLOCKED 狀態的線程列表，一般是由於線程停在了I/O、數據庫鏈接或網絡鏈接的地方。

關注點概況

在Thread Dump文件中，線程的狀態分紅兩種：Native Thread Status和JVM Thread Status，具體的含義能夠參考上一篇文章。在分析日誌的時候須要重點關注以下幾種線程狀態：

系統線程狀態爲 deadlock

線程處於死鎖狀態，將佔用系統大量資源。

系統線程狀態爲 waiting for monitor entry 或 in Object.wait()

如上一篇文章中所說，系統線程處於這種狀態說明它在等待進入一個臨界區，此時JVM線程的狀態一般都是 java.lang.Thread.State: BLOCKED。

若是大量線程處於這種狀態的話，多是一個全局鎖阻塞了大量線程。若是短時間內屢次打印Thread Dump信息，發現 waiting for monitor entry 狀態的線程愈來愈多，沒有減小的趨勢，可能意味着某些線程在臨界區裏呆得時間太長了，以致於愈來愈多新線程遲遲沒法進入。

系統線程狀態爲 waiting on condition

系統線程處於此種狀態說明它在等待另外一個條件的發生來喚醒本身，或者本身調用了sleep()方法。此時JVM線程的狀態一般是java.lang.Thread.State: WAITING (parking)（等待喚醒條件）或java.lang.Thread.State: TIMED_WAITING (parking或sleeping)（等待定時喚醒條件）。

若是大量線程處於此種狀態，說明這些線程又去獲取第三方資源了，好比第三方的網絡資源或讀取數據庫的操做，長時間沒法得到響應，致使大量線程進入等待狀態。所以，這說明系統處於一個網絡瓶頸或讀取數據庫操做時間太長。

系統線程狀態爲 blocked

線程處於阻塞狀態，須要根據實際狀況進行判斷。

案例分析

下面經過幾個案例進行分解來得到解決問題的方法。

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堆內存信息來進一步找到問題的緣由。