原文地址: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堆內存信息來進一步找到問題的原因。