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


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

症狀及解決方案

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

CPU占用率很高,響應很慢

按照《Java內存泄漏分析系列之一:使用jstack定位線程堆棧信息》中所說的方法,先找到占用CPU的進程,然后再定位到對應的線程,最后分析出對應的堆棧信息。
在同一時間多次使用上述的方法,然后進行對比分析,從代碼中找到問題所在的原因。如果線程指向的是"VM Thread"或者無法從代碼中直接找到原因,就需要進行內存分析,具體的見下一篇文章。

CPU占用率不高,但響應很慢

在整個請求的過程中多次執行Thread Dump然后進行對比,取得 BLOCKED 狀態的線程列表,通常是因為線程停在了I/O、數據庫連接或網絡連接的地方。

關注點概況

在Thread Dump文件中,線程的狀態分成兩種:Native Thread StatusJVM 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堆內存信息來進一步找到問題的原因。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM