1. 程式人生 > >【伺服器效能】第二篇 分析執行緒日誌

【伺服器效能】第二篇 分析執行緒日誌

1,執行緒狀態為“waiting for monitor entry”:

意味著它 在等待進入一個臨界區 ,所以它在”Entry Set“佇列中等待。

此時執行緒狀態一般都是 Blocked:

  • java.lang.Thread.State: BLOCKED (on object monitor)

2,執行緒狀態為“waiting on condition”:

說明它在等待另一個條件的發生,來把自己喚醒,或者乾脆它是呼叫了 sleep(N)。

此時執行緒狀態大致為以下幾種:

  • java.lang.Thread.State: WAITING (parking):一直等那個條件發生;
  • java.lang.Thread.State: TIMED_WAITING (parking或sleeping):定時的,那個條件不到來,也將定時喚醒自己。

3,如果大量執行緒在“waiting for monitor entry”:

可能是一個全域性鎖阻塞住了大量執行緒。

如果短時間內列印的 thread dump 檔案反映,隨著時間流逝,waiting for monitor entry 的執行緒越來越多,沒有減少的趨勢,可能意味著某些執行緒在臨界區裡呆的時間太長了,以至於越來越多新執行緒遲遲無法進入臨界區

4,如果大量執行緒在waiting on condition

”:

可能是它們又跑去獲取第三方資源,尤其是第三方網路資源,遲遲獲取不到Response,導致大量執行緒進入等待狀態。

所以如果你發現有大量的執行緒都處在 Wait on condition,從執行緒堆疊看,正等待網路讀寫,這可能是一個網路瓶頸的徵兆,因為網路阻塞導致執行緒無法執行。

執行緒狀態為“in Object.wait()”:

說明它獲得了監視器之後,又呼叫了 java.lang.Object.wait() 方法

每個 Monitor在某個時刻,只能被一個執行緒擁有,該執行緒就是 “Active Thread”,而其它執行緒都是 “Waiting Thread”,分別在兩個佇列 “ Entry Set”和 “Wait Set”裡面等候。在 “Entry Set”中等待的執行緒狀態是 “Waiting for monitor entry”,而在 “Wait Set”中等待的執行緒狀態是 “in Object.wait()”。

當執行緒獲得了 Monitor,如果發現執行緒繼續執行的條件沒有滿足,它則呼叫物件(一般就是被 synchronized 的物件)的 wait() 方法,放棄了 Monitor,進入 “Wait Set”佇列。

此時執行緒狀態大致為以下幾種:

  • java.lang.Thread.State: TIMED_WAITING (on object monitor);
  • java.lang.Thread.State: WAITING (on object monitor);

一般都是RMI相關執行緒(RMI RenewClean、 GC Daemon、RMI Reaper),GC執行緒(Finalizer),引用物件垃圾回收執行緒(Reference Handler)等系統執行緒處於這種狀態。

Java Monitor

圖1 A Java Monitor

示範一:

下面這個執行緒在等待這個鎖 0x00000000fe7e3b50,等待進入臨界區:

"RMI TCP Connection(64896)-172.16.52.118" daemon prio=10 tid=0x00000000405a6000 nid=0x68fe waiting for monitor entry [0x00007f2be65a3000]

   java.lang.Thread.State: BLOCKED (on object monitor)

at com.xyz.goods.service.impl.GoodsServiceImpl.findChanellGoodsCountWithCache(GoodsServiceImpl.java:1734)

waiting to lock <0x00000000fe7e3b50> (a java.lang.String)

那麼誰持有這個鎖呢?

是另一個先呼叫了 findChanellGoodsCountWithCache 函式的執行緒:

"RMI TCP Connection(64878)-172.16.52.117" daemon prio=10 tid=0x0000000040822000 nid=0x6841 runnable [0x00007f2be76b3000]

   java.lang.Thread.State: RUNNABLE

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.read(SocketInputStream.java:129)

at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)

at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)

at java.io.BufferedInputStream.read(BufferedInputStream.java:317)

- locked <0x00000000af4ed638> (a java.io.BufferedInputStream)

at org.bson.io.Bits.readFully(Bits.java:35)

at org.bson.io.Bits.readFully(Bits.java:28)

at com.mongodb.Response.<init>(Response.java:35)

at com.mongodb.DBPort.go(DBPort.java:110)

- locked <0x00000000af442d48> (a com.mongodb.DBPort)

at com.mongodb.DBPort.go(DBPort.java:75)

- locked <0x00000000af442d48> (a com.mongodb.DBPort)

at com.mongodb.DBPort.call(DBPort.java:65)

at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:202)

at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:296)

at com.mongodb.DB.command(DB.java:152)

at com.mongodb.DBCollection.getCount(DBCollection.java:760)

at com.mongodb.DBCollection.getCount(DBCollection.java:731)

at com.mongodb.DBCollection.count(DBCollection.java:697)

at com.xyz.goods.manager.MongodbManager.count(MongodbManager.java:202)

at com.xyz.goods.service.impl.GoodsServiceImpl.findChanellGoodsCount(GoodsServiceImpl.java:1787)

at com.xyz.goods.service.impl.GoodsServiceImpl.findChanellGoodsCountWithCache(GoodsServiceImpl.java:1739)

locked <0x00000000fe7e3b50> (a java.lang.String)

示範二:

等待另一個條件發生來將自己喚醒:

"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)

1)“TIMED_WAITING (parking)”中的 timed_waiting 指等待狀態,但這裡指定了時間,到達指定的時間後自動退出等待狀態;parking指執行緒處於掛起中。

2)“waiting on condition”需要與堆疊中的“parking to wait for  <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack)” 結合來看。首先,本執行緒肯定是在等待某個條件的發生,來把自己喚醒。其次,SynchronousQueue 並不是一個佇列,只是執行緒之間移交資訊的機制,當我們把一個元素放入到 SynchronousQueue 中時必須有另一個執行緒正在等待接受移交的任務,因此這就是本執行緒在等待的條件。

示範三:

"RMI RenewClean-[172.16.50.182:4888]" daemon prio=10 tid=0x0000000040d2c800 nid=0x97e in Object.wait() [0x00007f9ccafd0000]

   java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on <0x0000000799b032d8> (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)

- locked <0x0000000799b032d8> (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)