三個例項演示 Java Thread Dump 日誌分析

Memento 發表於 2021-03-04

原文

執行緒狀態

  1. 死鎖, DeadLock, 多個執行緒呼叫間, 進入相互資源佔用, 導致一直等待無法釋放的情況;
  2. 執行中, Runnable, 指該執行緒正在執行狀態中, 該執行緒佔用了資源, 正在處理某個請求, 或者正在傳遞 SQL 到資料庫執行, 或對某個檔案操作, 或進行資料型別轉換等;
  3. 等待資源, Waiting on condition, 等待資源, 或等待某個條件的發生;(結合 stacktrace 分析)
    • 如果棧資訊明確是應用程式碼, 則證明該執行緒正在等待資源, 一般是大量讀取某資源, 且該資源採用了資源鎖的情況下, 執行緒進入了等待狀態, 等待資源的讀取;
    • 或者正在等待其他執行緒的執行;
    • 如果發現大量的執行緒處於 Waiting on condition, 從執行緒 stack 上看, 正等待網路的讀寫, 這可能是網路瓶頸的徵兆, 因為網路阻塞導致的執行緒無法執行;
      • 情況一, 是網路忙, 消耗了所有的頻寬, 仍然有大量資料等待網路的讀寫;
      • 情況二, 網路空閒, 但由於路由等問題, 導致包丟失無法正常到達;
    • 大部分這種狀態是因為執行緒處於 sleep, 等待 sleep 的時間到了時候被喚醒;
  4. 等待獲取監視器, Waiting on monitor entry
  5. 暫停, Suspended
  6. 物件等待中, Object.wait() or TIMED_WAITING
  7. 阻塞, Blocked, 執行緒阻塞, 指當前執行緒執行過程中, 所需要的資源長時間等待卻一直未能獲取到, 被容器的執行緒管理器標識為阻塞狀態, 可理解為等待資源超時的執行緒;
  8. 停止, Parked

Monitor 是 Java 中用以實現執行緒之間的互斥與協作的主要手段, 可以看成是物件或者 Class 的鎖; 每個物件都有, 也僅有一個 monitor;

三個例項演示 Java Thread Dump 日誌分析

每個 Monitor 在某個時刻, 只能被一個執行緒擁有, 該執行緒就是 Active Thread, 其他執行緒則處於 Waiting Thread, 分別在兩個佇列 Entry SetWait Set 裡面等待;
Entry Set 中等待的執行緒狀態是 Waiting for monitor entry;
Wait Set 中等待的執行緒是 in Object.wait();

示例一

"ForkJoinPool.commonPool-worker-37" #24464 daemon prio=5 os_prio=0 tid=0x00007f1bb418a800 nid=0x1fa12 waiting for monitor entry [0x00007f19a2054000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.util.concurrent.ConcurrentHashMap.computeIfPresent(ConcurrentHashMap.java:1760)
	- waiting to lock <0x00000005e20c0050> (a java.util.concurrent.ConcurrentHashMap$Node)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache.evictEntry(BoundedLocalCache.java:756)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache.expireAfterWriteEntries(BoundedLocalCache.java:717)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache.expireEntries(BoundedLocalCache.java:674)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache.maintenance(BoundedLocalCache.java:1136)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1108)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache$PerformCleanupTask.run(BoundedLocalCache.java:2979)
	at com.github.benmanes.caffeine.cache.BoundedLocalCache$PerformCleanupTask.exec(BoundedLocalCache.java:2968)
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
	at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

   Locked ownable synchronizers:
	- <0x00000005c4525180> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
  1. 執行緒狀態是 BLOCKED, 阻塞狀態, 說明執行緒等待資源超時;
  2. waiting to lock <0x00000005e20c0050> 表示執行緒正在等待給 0x00000005e20c0050 這個地址上鎖(等待獲取該地址的鎖);
  3. 查詢日誌中對應 0x00000005e20c0050 地址的 locked <0x00000005e20c0050> 位置, 就可以查出來當前誰獲得了這個鎖;

三個例項演示 Java Thread Dump 日誌分析

  1. waiting for monitor entry 表示此執行緒通過 synchronized(obj){...} 方式申請進入裡臨界區, 從而進入了 Entry Set 佇列, 但是該 obj 對應的 monitor 被其他執行緒擁有, 所以該執行緒在 Entry Set 佇列中等待;
  2. tid=thread id, nid=native 執行緒的 id, prio=執行緒優先順序, 0x00007f19a2054000=執行緒棧起始地址;

示例二

"http-nio-58032-exec-479" #25175 daemon prio=5 os_prio=0 tid=0x00007f1c342d2800 nid=0x2d2fa waiting on condition [0x00007f1982a27000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000072740b888> (a java.util.concurrent.CompletableFuture$Signaller)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1695)
	at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
	at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
	at io.lettuce.core.protocol.AsyncCommand.await(AsyncCommand.java:83)
	at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:112)
	at io.lettuce.core.cluster.ClusterFutureSyncInvocationHandler.handleInvocation(ClusterFutureSyncInvocationHandler.java:123)
	at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
  1. TIMED_WAITING (parking) 表示等待狀態, 但是指定了等待時間, 到達指定的時間後自動退出等待狀態; parking 表示執行緒處於掛起狀態;
  2. waiting on conditionparking to wait for <0x000000072740b888> 結合來看, 該執行緒肯定是在等待某個條件觸發來喚醒自己;

示例三

"http-nio-58032-exec-307" #24690 daemon prio=5 os_prio=0 tid=0x00007f1c341b0800 nid=0x25e19 in Object.wait() [0x00007f199477a000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at org.apache.http.concurrent.BasicFuture.get(BasicFuture.java:82)
	- locked <0x00000007162a9628> (a org.apache.http.concurrent.BasicFuture)
	at org.apache.http.impl.nio.client.FutureWrapper.get(FutureWrapper.java:70)
  1. Wait Set 佇列中等待的執行緒狀態就是 in Object.wait(); 當執行緒獲得了 Monitor, 進入了臨界區之後, 如果發現執行緒繼續執行的條件沒有滿足, 則會呼叫物件(一般是被 synchronize 的物件) 的 wait() 方法, 放棄了 Monitor, 進入 Wait Set 佇列; 只有當別的執行緒在該物件上呼叫 notify() 或者 notifyAll() 時, Wait Set 佇列中的執行緒才得到機會去競爭; 但是也只有一個執行緒會獲得物件的 Monitor, 恢復到執行態;
  2. BasicFutureget 方法, 表示非同步請求時等待結果返回;

參考資料

  1. 三個例項演示 Java Thread Dump 日誌分析