JAVA Thread Dump 檔案分析

Thread Dump介紹

Thread Dump是非常有用的診斷Java應用問題的工具，每一個Java虛擬機都有及時生成所有執行緒在某一點狀態的thread-dump的能力，雖然各個 Java虛擬機列印的thread dump略有不同，但是大多都提供了每個執行緒的所有資訊，例如: 執行緒狀態、執行緒 Id、本機 Id、執行緒名稱、堆疊跟蹤、優先級，

Thread Dump特點

能在各種作業系統下使用
能在各種Java應用服務器下使用
可以在生產環境下使用而不影響系統的性能
可以將問題直接定位到應用程式的代碼行上(對于線上排查問題非常有用)

它能幫我們解決哪些線上問題?

Thread dump 能幫我們定位到例如 CPU 峰值、應用程式中的無回應性、回應時間差、執行緒掛起、高記憶體消耗，

如何抓取Thread Dump

一般當服務器掛起,崩潰或者性能底下時,就需要抓取服務器的執行緒堆疊(Thread Dump)用于后續的分析. 在實際運行中，往往一次 dump的資訊，還不足以確認問題，為了反映執行緒狀態的動態變化，需要接連多次做threaddump，每次間隔10-20s，建議至少產生三次 dump資訊，如果每次 dump都指向同一個問題，我們才確定問題的典型性，

獲取thread dump

JDK自帶命令列工具獲取PID，再獲取ThreadDump:

1. jps 或 ps –ef|grep java (獲取PID)

2. jstack [-l ]<pid> | tee -a jstack.log  (獲取ThreadDump)

實操演練

獲取所有執行緒的thread dump 分兩步.

第一步獲取行程的PID
使用Jps 獲取所有java行程的資訊

第二步選取對應的pid 例如上圖紅框中的數字串使用Jstack獲取所有執行緒堆疊資訊

jstack  -l  9468 | tee -a jstack.log

日志欄位分析

我們把Thread dump檔案分為2個部分來理解

拿我們的例子來說:

//頭部資訊  包含 當前時間  jvm資訊
2021-01-14 17:00:51
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

//執行緒info資訊塊
"ajp-nio-8019-exec-7" #75 daemon prio=5 os_prio=0 tid=0x00007fa0cc37e800 nid=0x2af3 waiting on condition [0x00007fa02eceb000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f183aa30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

執行緒info資訊塊各個引數的意義:

執行緒名稱：ajp-nio-8019-exec-7
執行緒型別：daemon
優先級: 默認是5
jvm執行緒id：tid=0x00007fa0cc37e800，jvm內部執行緒的唯一標識（通過java.lang.Thread.getId()獲取，通常用自增方式實作，）
對應系統執行緒id（NativeThread ID）：nid=0x2af3，和top命令查看的執行緒pid對應，不過一個是10進制，一個是16進制，（通過命令：top -H -p pid，可以查看該行程的所有執行緒資訊）
執行緒狀態：java.lang.Thread.State: WAITING (parking)
執行緒呼叫堆疊資訊：用于代碼的分析，堆疊資訊應該從下向上解讀，因為程式呼叫的順序是從下向上的，

系統執行緒狀態 (Native Thread Status)

系統執行緒有如下狀態：

deadlock
死鎖執行緒，一般指多個執行緒呼叫期間進入了相互資源占用，導致一直等待無法釋放的情況，
runnable
一般指該執行緒正在執行狀態中，該執行緒占用了資源，正在處理某個操作，如通過SQL陳述句查詢資料庫、對某個檔案進行寫入等，
blocked
執行緒正處于阻塞狀態，指當前執行緒執行程序中，所需要的資源長時間等待卻一直未能獲取到，被容器的執行緒管理器標識為阻塞狀態，可以理解為等待資源超時的執行緒，
waiting on condition
執行緒正處于等待資源或等待某個條件的發生，具體的原因需要結合下面堆疊資訊進行分析，

（1）如果堆疊資訊明確是應用代碼，則證明該執行緒正在等待資源，一般是大量讀取某種資源且該資源采用了資源鎖的情況下，執行緒進入等待狀態，等待資源的讀取，或者正在等待其他執行緒的執行等，

（2）如果發現有大量的執行緒都正處于這種狀態，并且堆疊資訊中得知正等待網路讀寫，這是因為網路阻塞導致執行緒無法執行，很有可能是一個網路瓶頸的征兆：

網路非常繁忙，幾乎消耗了所有的帶寬，仍然有大量資料等待網路讀寫；
網路可能是空閑的，但由于路由或防火墻等原因，導致包無法正常到達；
所以一定要結合系統的一些性能觀察工具進行綜合分析，比如netstat統計單位時間的發送包的數量，看是否很明顯超過了所在網路帶寬的限制；觀察CPU的利用率，看系統態的CPU時間是否明顯大于用戶態的CPU時間，這些都指向由于網路帶寬所限導致的網路瓶頸，

（3）還有一種常見的情況是該執行緒在 sleep，等待 sleep 的時間到了，將被喚醒，

waiting for monitor entry 或 in Object.wait()
Moniter 是Java中用以實作執行緒之間的互斥與協作的主要手段，它可以看成是物件或者class的鎖，每個物件都有，也僅有一個 Monitor，

從上圖可以看出，每個Monitor在某個時刻只能被一個執行緒擁有，該執行緒就是 "Active Thread"，而其他執行緒都是 "Waiting Thread"，分別在兩個佇列 "Entry Set"和"Wait Set"里面等待，其中在 "Entry Set" 中等待的執行緒狀態是 waiting for monitor entry，在 "Wait Set" 中等待的執行緒狀態是 in Object.wait()，

（1）"Entry Set"里面的執行緒，
我們稱被 synchronized 保護起來的代碼段為臨界區，對應的代碼如下：

synchronized(obj) {

}

當一個執行緒申請進入臨界區時，它就進入了 "Entry Set" 佇列中，這時候有兩種可能性：

該Monitor不被其他執行緒擁有，"Entry Set"里面也沒有其他等待的執行緒，本執行緒即成為相應類或者物件的Monitor的Owner，執行臨界區里面的代碼；此時在Thread Dump中顯示執行緒處于 "Runnable" 狀態，
該Monitor被其他執行緒擁有，本執行緒在 "Entry Set" 佇列中等待，此時在Thread Dump中顯示執行緒處于 "waiting for monity entry" 狀態，
臨界區的設定是為了保證其內部的代碼執行的原子性和完整性，但因為臨界區在任何時間只允許執行緒串行通過，這和我們使用多執行緒的初衷是相反的，如果在多執行緒程式中大量使用synchronized，或者不適當的使用它，會造成大量執行緒在臨界區的入口等待，造成系統的性能大幅下降，如果在Thread Dump中發現這個情況，應該審視原始碼并對其進行改進，

（2）"Wait Set"里面的執行緒
當執行緒獲得了Monitor，進入了臨界區之后，如果發現執行緒繼續運行的條件沒有滿足，它則呼叫物件（通常是被synchronized的物件）的wait()方法，放棄Monitor，進入 "Wait Set"佇列，只有當別的執行緒在該物件上呼叫了 notify()或者notifyAll()方法，"Wait Set"佇列中的執行緒才得到機會去競爭，但是只有一個執行緒獲得物件的Monitor，恢復到運行態，"Wait Set"中的執行緒在Thread Dump中顯示的狀態為 in Object.wait()，

通常來說，當CPU很忙的時候關注 Runnable 狀態的執行緒，反之則關注 waiting for monitor entry 狀態的執行緒，

JVM執行緒狀態

NEW：
每一個執行緒，在堆記憶體中都有一個對應的Thread物件， Thread t = new Thread();當剛剛在堆記憶體中創建Thread物件，還沒有呼叫t.start()方法之前，執行緒就處在NEW狀態，在這個狀態上，執行緒與普通的java物件沒有什么區別，就僅僅是一個堆記憶體中的物件，

RUNNABLE：
該狀態表示執行緒具備所有運行條件，在運行佇列中準備作業系統的調度，或者正在運行，這個狀態的執行緒比較正常，但如果執行緒長時間停留在在這個狀態就不正常了，這說明執行緒運行的時間很長（存在性能問題），或者是執行緒一直得不得執行的機會（存在執行緒饑餓的問題），

BLOCKED：
執行緒正在等待獲取java物件的監視器(也叫內置鎖)，即執行緒正在等待進入由synchronized保護的方法或者代碼塊， synchronized用來保證原子性，任意時刻最多只能由一個執行緒進入該臨界區域，其他執行緒只能排隊等待，

WAITING：
處在該執行緒的狀態，正在等待某個事件的發生，只有特定的條件滿足，才能獲得執行機會，而產生這個特定的事件，通常都是另一個執行緒，也就是說，如果不發生特定的事件，那么處在該狀態的執行緒一直等待，不能獲取執行的機會，比如：
A執行緒呼叫了obj物件的obj.wait()方法，如果沒有執行緒呼叫obj.notify或obj.notifyAll，那么A執行緒就沒有辦法恢復運行；如果A執行緒呼叫了LockSupport.park()，沒有別的執行緒呼叫LockSupport.unpark(A)，那么A沒有辦法恢復運行，

TIMED_WAITING：
J.U.C中很多與執行緒相關類，都提供了限時版本和不限時版本的API，TIMED_WAITING意味著執行緒呼叫了限時版本的API，正在等待時間流逝，當等待時間過去后，執行緒一樣可以恢復運行，如果執行緒進入了WAITING狀態，一定要特定的事件發生才能恢復運行；而處在TIMED_WAITING的執行緒，如果特定的事件發生或者是時間流逝完畢，都會恢復運行，

TERMINATED：
執行緒執行完畢，執行完run方法正常回傳，或者拋出了運行時例外而結束，執行緒都會停留在這個狀態，這個時候執行緒只剩下Thread物件了，沒有什么用了，

根據dump日志分析

下面我們根據實際的代碼來分析dump日志,可以更加透明的了解執行緒為什么是這個狀態

例子1:

等待釋放鎖

package jstack;
 
 
public class BlockedState
{
	private static Object object = new Object();
 
	public static void main(String[] args)
	{
		Runnable task = new Runnable() {
 
			@Override
			public void run()
			{
				synchronized (object)
				{
					long begin = System.currentTimeMillis();
 
					long end = System.currentTimeMillis();
 
					// 讓執行緒運行5分鐘,會一直持有object的監視器
					while ((end - begin) <= 5 * 60 * 1000)
					{
 
					}
				}
			}
		};
 
		new Thread(task, "t1").start();
		new Thread(task, "t2").start();
	}
}

先獲取object的執行緒會執行5分鐘，這5分鐘內會一直持有object的監視器，另一個執行緒無法執行處在BLOCKED狀態


"t2" prio=6 tid=0x27d7a800 nid=0x1350 waiting for monitor entry [0x2833f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at jstack.BlockedState$1.run(BlockedState.java:17)
        - waiting to lock <0x1cfcdc00> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:662)

"t1" prio=6 tid=0x27d79400 nid=0x1338 runnable [0x282ef000]
   java.lang.Thread.State: RUNNABLE
        at jstack.BlockedState$1.run(BlockedState.java:22)
        - locked <0x1cfcdc00> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:662)

通過thread dump可以看到：t2執行緒在BLOCKED (on object monitor)，waiting for monitor entry 等待進入synchronized保護的區域，但obj對應的 Monitor 被其他執行緒所擁有，所以 JVM執行緒的狀態是 java.lang.Thread.State: BLOCKED (on object monitor)，說明執行緒等待資源，

例子2:

死鎖

public class DeadLock {
    
    public static void main(String[] args) {
        final Object resource1 = "resource1";
        final Object resource2 = "resource2";

        Thread t1 = new Thread(){
            public void run(){
                synchronized(resource1){
                    System.out.println("Thread1:locked resource1");
                    try{
                        Thread.sleep(50);
                    }catch(Exception ex){

                    }
                    synchronized(resource2){
                        System.out.println("Thread1:locked resource2");
                    }
                }
            }
        };

        Thread t2 = new Thread(){
            public void run(){
                synchronized(resource2){
                    System.out.println("Thread2:locked resource2");
                    try{
                        Thread.sleep(50);
                    }catch(Exception ex){

                    }
                    synchronized(resource1){
                        System.out.println("Thread2:locked resource1");
                    }
                }
            }
        };

        t1.start();
        t2.start();
    }
}

我們的這段代碼是讓兩個執行緒互相等待物件釋放鎖,造成死鎖的情況,在這種情況下,獲取Thread dump檔案我們會發現jvm已經提示我們死鎖了如下:


"Thread-1" #20 prio=5 os_prio=31 tid=0x00007fb76c0e1800 nid=0x9d03 waiting for monitor entry [0x0000700004dbf000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at DeadLock$2.run(DeadLock.java:35)
        - waiting to lock <0x000000076af61870> (a java.lang.String)
        - locked <0x000000076af618b0> (a java.lang.String)

"Thread-0" #19 prio=5 os_prio=31 tid=0x00007fb76c002800 nid=0x9e03 waiting for monitor entry [0x0000700004cbc000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at DeadLock$1.run(DeadLock.java:19)
        - waiting to lock <0x000000076af618b0> (a java.lang.String)
        - locked <0x000000076af61870> (a java.lang.String)



Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007fb769825b58 (object 0x000000076af61870, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00007fb769823168 (object 0x000000076af618b0, a java.lang.String),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at DeadLock$2.run(DeadLock.java:35)
        - waiting to lock <0x000000076af61870> (a java.lang.String)
        - locked <0x000000076af618b0> (a java.lang.String)
"Thread-0":
        at DeadLock$1.run(DeadLock.java:19)
        - waiting to lock <0x000000076af618b0> (a java.lang.String)
        - locked <0x000000076af61870> (a java.lang.String)

Found 1 deadlock.

例子3

呼叫wait()，sleep()對應的執行緒狀態

    public static void main(String[] args) {

        Thread thread = new Thread("執行緒1") {
            //重寫run方法
            public void run() {
                synchronized (this) {
                    System.out.println(Thread.currentThread().getName());
                    try {
                        wait();
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
        };
        thread.start();
        try {
            TimeUnit.SECONDS.sleep(3);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        synchronized (thread) {
            System.out.println(Thread.currentThread().getName());
            try {
                TimeUnit.SECONDS.sleep(60);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            thread.notify();
        }


    }

上面代碼會先執行執行緒1 run()方法，然后呼叫wait()方法阻塞block住，等到主執行緒呼叫thread.notify()方法之后才會繼續往下執行，我們在程式跑起來之后大概10秒時候匯出thread dump日志檔案資訊，此時：

"執行緒1" #12 prio=5 os_prio=0 tid=0x00007f420024d800 nid=0x1ca5 in Object.wait() [0x00007f41e71ee000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
	at java.lang.Object.wait(Object.java:502)
	at com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1.run(ObjectWaitingMock.java:15)
	- locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)

   Locked ownable synchronizers:
	- None

....(其他資訊這里我們省略掉)

"main" #1 prio=5 os_prio=0 tid=0x00007f420000d800 nid=0x1c84 waiting on condition [0x00007f4209891000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at java.lang.Thread.sleep(Thread.java:340)
	at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
	at com.jvm.study.threaddump.deadlock.ObjectWaitingMock.main(ObjectWaitingMock.java:31)
	- locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)

   Locked ownable synchronizers:
	- None

[執行緒1]執行緒：wait()方法阻塞住了，狀態對應in Object.wait()，狀態詳細資訊對應java.lang.Thread.State: WAITING (on object monitor)，
[main]執行緒：TimeUnit.SECONDS.sleep(60)阻塞住了，狀態對應waiting on condition，狀態詳細資訊對應java.lang.Thread.State: TIMED_WAITING (sleeping)，

根據案例癥狀分析解決方案

1 CPU占用率不高，但回應很慢

在整個請求的程序中多次執行Thread Dump然后進行對比，取得 BLOCKED狀態的執行緒串列，通常是因為執行緒停在了I/O、資料庫連接或網路連接的地方，

2 CPU飆高，load高，回應很慢

一個請求程序中多次dump；對比多次dump檔案的runnable執行緒，如果執行的方法有比較大變化，說明比較正常，如果在執行同一個方法，就有一些問題了；先找到占用CPU的行程，然后再定位到對應的執行緒，最后分析出對應的堆疊資訊，
在同一時間多次使用上述的方法，然后進行對比分析，從代碼中找到問題所在的原因.

3 請求無法回應

多次dump，檢查是否有 Found one Java-level deadlock提示,死鎖經常表現為程式的停頓，或者不再回應用戶的請求，從作業系統上觀察，對應行程的CPU占用率為零，很快會從top或prstat的輸出中消失，

關注公眾號:java寶典

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/249307.html

標籤：Java

上一篇：PMP基本概念

下一篇：IntelliJ IDEA啟動界面的秘密：當編程遇到藝術

JVM Thread Dump 檔案分析