JDK指令二、jstack(Java Stack Trace)

jstack是java虛拟機自帶的一種堆棧跟蹤工具。

基本介紹

jstack用于生成java虛拟機目前時刻的線程快照。線程快照是目前java虛拟機内每一條線程正在執行的方法堆棧的集合，生成線程快照的主要目的是定位線程出現長時間停頓的原因，如線程間死鎖、死循環、請求外部資源導緻的長時間等待等。

線程出現停頓的時候通過jstack來檢視各個線程的調用堆棧，就可以知道沒有響應的線程到底在背景做什麼事情，或者等待什麼資源。

指令格式

jstack [ option ] pid

基本參數：

-F 當’jstack [-l] pid’沒有響應的時候強制列印棧資訊

-l 長清單. 列印關于鎖的附加資訊,例如屬于java.util.concurrent的ownable synchronizers清單.

-m 列印java和native c/c++架構的所有棧資訊. -h | -help列印幫助資訊

pid 需要被列印配置資訊的java程序id,可以用jps工具查詢.

案例

說明

不同的 JAVA虛機的線程 DUMP的建立方法和檔案格式是不一樣的，不同的 JVM版本， dump資訊也有差别。
在實際運作中，往往一次 dump的資訊，還不足以确認問題。建議産生三次 dump資訊，如果每次 dump都指向同一個問題，我們才确定問題的典型性。

案例1-使用

先以一個小場景簡單示範下 jstack 的使用。

場景：Java應用持續占用很高CPU，需要排查一下。

模拟：造個場景簡單模拟下，沒什麼實際意義，僅作示範。我啟動了100個線程持續通路我的部落格，部落格部署在Ubuntu 16.04上，是一個簡單的Spring Boot應用，以jar包直接運作的。

top 指令查下系統運作情況，程序31951占用CPU 80.6%。

JDK指令二、jstack(Java Stack Trace)

top -Hp 31951

以線程模式檢視下程序31951的所有線程情況

JDK指令二、jstack(Java Stack Trace)

假設想看下第二個線程31998的情況，31998是作業系統的線程ID，先轉成16進制。（再例如：21233用電腦轉換為16進制52f1，注意字母是小寫）

printf '%x' 31998 #值為7cfe

擷取該線程的資訊(比對7cf3後取20行差不多)

jstack 31951 | grep 7cfe -A 20

其中部分資料如下：

"Tomcat JDBC Pool Cleaner[11483240:1532362388783]" #31 daemon prio=5 os_prio=0 tid=0x0a29dc00 nid=0x7cfe in Object.wait() [0xa2a69000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0xaadc5a60> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

注意：nid=0x7cfe中的nid指native id，是OS中線程ID，對應上面31998線程的16進制值7cfe；tid為Java中線程的ID。

至于如何利用jstack的資料分析線程情況，可以看看如何使用jstack分析線程狀态和 jstack。

案例2-死鎖

在多線程程式的編寫中，如果不适當的運用同步機制，則有可能造成程式的死鎖，經常表現為程式的停頓，或者不再響應使用者的請求。比如在下面這個示例中，是個較為典型的死鎖情況：

dump結果

"Thread-1"prio=5tid=0x00acc490nid=0xe50waitingformonitorentry[0x02d3f000

..0x02d3fd68]

atdeadlockthreads.TestThread.run(TestThread.java:31)

-waitingtolock<0x22c19f18>(ajava.lang.Object)

-locked<0x22c19f20>(ajava.lang.Object)

"Thread-0"prio=5tid=0x00accdb0nid=0xdecwaitingformonitorentry[0x02cff000

..0x02cff9e8]

atdeadlockthreads.TestThread.run(TestThread.java:31)

-waitingtolock<0x22c19f20>(ajava.lang.Object)

-locked<0x22c19f18>(ajava.lang.Object)

在 JAVA 5中加強了對死鎖的檢測。線程 Dump中可以直接報告出 Java級别的死鎖，如下所示：

dump結果

FoundoneJava-leveldeadlock:

=============================

"Thread-1":

waitingtolockmonitor0x0003f334(object0x22c19f18,ajava.lang.Object),

whichisheldby"Thread-0"

"Thread-0":

waitingtolockmonitor0x0003f314(object0x22c19f20,ajava.lang.Object),

whichisheldby"Thread-1"[2]

生成死鎖（deadlock）的源代碼

/**
 * 簡單的應用,供測試JDK自帶的jstack使用 本應用會造成deadlock，可能會導緻系統崩潰
 * 邏輯：一旦兩個線程互相等待的局面出現，死鎖（deadlock）就發生了
 */
public class EasyJstack extends Thread {

    private EasyJstackResource resourceManger;// 資源管理類的私有引用，通過此引用可以通過其相關接口對資源進行讀寫
    private int a, b;// 将要寫入資源的資料

    public static void main(String[] args) throws Exception {
        EasyJstackResource resourceManager = new EasyJstackResource();
        EasyJstack stack1 = new EasyJstack(resourceManager, 1, 2);
        EasyJstack stack2 = new EasyJstack(resourceManager, 3, 4);
        stack1.start();
        stack2.start();
    }

    public EasyJstack(EasyJstackResource resourceManager, int a, int b) {
        this.resourceManger = resourceManager;
        this.a = a;
        this.b = b;
    }

    public void run() {
        while (true) {
            this.resourceManger.read();
            this.resourceManger.write(this.a, this.b);
        }
    }

}

public class EasyJstackResource {
    /**
     * 管理的兩個資源，如果有多個線程并發，那麼就會死鎖
     */
    private Resource resourceA = new Resource();
    private Resource resourceB = new Resource();

    public EasyJstackResource() {
        this.resourceA.setValue(0);
        this.resourceB.setValue(0);
    }

    public int read() {
        synchronized (this.resourceA) {
            System.out.println(Thread.currentThread().getName() + "線程拿到了資源 resourceA的對象鎖");
            synchronized (resourceB) {
                System.out.println(Thread.currentThread().getName() + "線程拿到了資源 resourceB的對象鎖");
                return this.resourceA.getValue() + this.resourceB.getValue();
            }
        }
    }

    public void write(int a, int b) {
        synchronized (this.resourceB) {
            System.out.println(Thread.currentThread().getName() + "線程拿到了資源 resourceB的對象鎖");
            synchronized (this.resourceA) {
                System.out.println(Thread.currentThread().getName() + "線程拿到了資源 resourceA的對象鎖");
                this.resourceA.setValue(a);
                this.resourceB.setValue(b);
            }
        }
    }

    public class Resource {
        private int value;// 資源的屬性

        public int getValue() {
            return value;
        }

        public void setValue(int value) {
            this.value = value;
        }
    }
}

用jstack進行分析和結果

Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00000000577c2bc8 (object 0x00000000d7149440, a com.dxz.jstack.EasyJstackResource$Resource),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00000000577c4118 (object 0x00000000d7149428, a com.dxz.jstack.EasyJstackResource$Resource),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at com.dxz.jstack.EasyJstackResource.read(EasyJstackResource.java:36)
        - waiting to lock <0x00000000d7149440> (a com.dxz.jstack.EasyJstackResource$Resource)
        - locked <0x00000000d7149428> (a com.dxz.jstack.EasyJstackResource$Resource)
        at com.dxz.jstack.EasyJstack.run(EasyJstack.java:41)
"Thread-0":
        at com.dxz.jstack.EasyJstackResource.write(EasyJstackResource.java:46)
        - waiting to lock <0x00000000d7149428> (a com.dxz.jstack.EasyJstackResource$Resource)
        - locked <0x00000000d7149440> (a com.dxz.jstack.EasyJstackResource$Resource)
        at com.dxz.jstack.EasyJstack.run(EasyJstack.java:42)

Found 1 deadlock.

仔細看這一段文字，告訴我們 EasyJstackResource.java:36出了狀況。如果出現了這種情況，我們就要從這裡開始順藤摸瓜，解決問題。

=========================================================

jstack用于列印出給定的Java程序ID或core file或遠端調試服務的Java堆棧資訊，如果是在64位機器上，需要指定選項"-J-d64"，Windows的jstack使用方式隻支援以下的這種方式：jstack [-l] pid

如果java程式崩潰生成core檔案，jstack工具可以用來獲得core檔案的java stack和native stack的資訊，進而可以輕松地知道java程式是如何崩潰和在程式何處發生問題。另外，jstack工具還可以附屬到正在運作的java程式中，看到當時運作的java程式的java stack和native stack的資訊, 如果現在運作的java程式呈現hung的狀态，jstack是非常有用的。

需要注意的問題:

l 不同的 JAVA虛機的線程 DUMP的建立方法和檔案格式是不一樣的，不同的 JVM版本， dump資訊也有差别。

l 在實際運作中，往往一次 dump的資訊，還不足以确認問題。建議産生三次 dump資訊，如果每次 dump都指向同一個問題，我們才确定問題的典型性。

2、指令格式

$jstack [ option ] pid

$jstack [ option ] executable core

$jstack [ option ] [server-id@]remote-hostname-or-IP

參數說明:

pid: java應用程式的程序号,一般可以通過jps來獲得;

executable:産生core dump的java可執行程式;

core:列印出的core檔案;

remote-hostname-or-ip:遠端debug伺服器的名稱或IP;

server-id: 唯一id,假如一台主機上多個遠端debug服務;

示例:

$jstack –l 23561

線程分析:

一般情況下，通過jstack輸出的線程資訊主要包括：jvm自身線程、使用者線程等。其中jvm線程會在jvm啟動時就會存在。對于使用者線程則是在使用者通路時才會生成。

l jvm線程：

線上程中，有一些 JVM内部的背景線程，來執行譬如垃圾回收，或者低記憶體的檢測等等任務，這些線程往往在JVM初始化的時候就存在，如下所示：

"Attach Listener" daemon prio=10 tid=0x0000000052fb8000 nid=0xb8f waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:

- None

destroyJavaVM" prio=10 tid=0x00002aaac1225800 nid=0x7208 waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:

- None

l 使用者級别的線程

還有一類線程是使用者級别的，它會根據使用者請求的不同而發生變化。該類線程的運作情況往往是我們所關注的重點。而且這一部分也是最容易産生死鎖的地方。

"qtp496432309-42" prio=10 tid=0x00002aaaba2a1800 nid=0x7580 waiting on condition [0x00000000425e9000]

java.lang.Thread.State: TIMED_WAITING (parking)

at sun.misc.Unsafe.park(Native Method)

- parking to wait for <0x0000000788cfb020> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)

at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:479)

at java.lang.Thread.run(Thread.java:662)

Locked ownable synchronizers:

- None

從上述的代碼示例中我們可以看到該使用者線程的以下幾類資訊：

Ø 線程的狀态：waiting on condition(等待條件發生)

Ø 線程的調用情況；

Ø 線程對資源的鎖定情況；

線程的狀态分析：

正如我們剛看到的那樣，線程的狀态是一個重要的名額，它會顯示線上程每行結尾的地方。那麼線程常見的有哪些狀态呢？線程在什麼樣的情況下會進入這種狀态呢？我們能從中發現什麼線索？

l Runnable

該狀态表示線程具備所有運作條件，在運作隊列中準備作業系統的排程，或者正在運作。

l Waiton condition

該狀态出現線上程等待某個條件的發生。具體是什麼原因，可以結合stacktrace來分析。最常見的情況是線程在等待網絡的讀寫，比如當網絡資料沒有準備好讀時，線程處于這種等待狀态，而一旦有資料準備好讀之後，線程會重新激活，讀取并處理資料。在 Java引入 NIO之前，對于每個網絡連接配接，都有一個對應的線程來處理網絡的讀寫操作，即使沒有可讀寫的資料，線程仍然阻塞在讀寫操作上，這樣有可能造成資源浪費，而且給作業系統的線程排程也帶來壓力。在 NIO裡采用了新的機制，編寫的伺服器程式的性能和可擴充性都得到提高。

如果發現有大量的線程都在處在 Wait on condition，從線程 stack看，正等待網絡讀寫，這可能是一個網絡瓶頸的征兆。因為網絡阻塞導緻線程無法執行。一種情況是網絡非常忙，幾乎消耗了所有的帶寬，仍然有大量資料等待網絡讀寫；另一種情況也可能是網絡空閑，但由于路由等問題，導緻包無法正常的到達。是以要結合系統的一些性能觀察工具來綜合分析，比如 netstat統計機關時間的發送包的數目，如果很明顯超過了所在網絡帶寬的限制 ; 觀察 cpu的使用率，如果系統态的 CPU時間，相對于使用者态的 CPU時間比例較高；如果程式運作在 Solaris 10平台上，可以用 dtrace工具看系統調用的情況，如果觀察到 read/write的系統調用的次數或者運作時間遙遙領先；這些都指向由于網絡帶寬所限導緻的網絡瓶頸。

另外一種出現 Wait on condition的常見情況是該線程在 sleep，等待 sleep的時間到了時候，将被喚醒。

l Waitingfor monitor entry 和 in Object.wait()

在多線程的 JAVA程式中，實作線程之間的同步，就要說說Monitor。Monitor是Java中用以實作線程之間的互斥與協作的主要手段，它可以看成是對象或者 Class的鎖。每一個對象都有，也僅有一個 monitor。下面這個圖，描述了線程和 Monitor之間關系，以及線程的狀态轉換圖：

JDK指令二、jstack(Java Stack Trace)

從圖中可以看出，每個 Monitor在某個時刻，隻能被一個線程擁有，該線程就是 “Active Thread”，而其它線程都是 “Waiting Thread”，分别在兩個隊列 “ Entry Set”和 “Wait Set”裡面等候。在 “Entry Set”中等待的線程狀态是 “Waiting for monitorentry”，而在 “Wait Set”中等待的線程狀态是“in Object.wait()”。

先看 “Entry Set”裡面的線程。我們稱被 synchronized保護起來的代碼段為臨界區。當一個線程申請進入臨界區時，它就進入了 “Entry Set”隊列。對應的 code就像：

synchronized(obj){

.........

}

這時有兩種可能性：

該 monitor不被其它線程擁有，Entry Set裡面也沒有其它等待線程。本線程即成為相應類或者對象的 Monitor的 Owner，執行臨界區的代碼。此時線程将處于Runnable狀态；

該 monitor被其它線程擁有，本線程在 Entry Set隊列中等待。此時dump的資訊顯示“waiting for monitor entry”。

"Thread-0" prio=10 tid=0x08222eb0 nid=0x9 waiting for monitor entry [0xf927b000..0xf927bdb8]

at testthread.WaitThread.run(WaitThread.java:39)

- waiting to lock <0xef63bf08> (a java.lang.Object)

- locked <0xef63beb8> (a java.util.ArrayList)

at java.lang.Thread.run(Thread.java:595)

臨界區的設定，是為了保證其内部的代碼執行的原子性和完整性。但是因為臨界區在任何時間隻允許線程串行通過，這和我們多線程的程式的初衷是相反的。如果在多線程的程式中，大量使用 synchronized，或者不适當的使用了它，會造成大量線程在臨界區的入口等待，造成系統的性能大幅下降。如果線上程 DUMP中發現了這個情況，應該審查源碼，改程序式。

現在我們再來看現線上程為什麼會進入 “Wait Set”。當線程獲得了 Monitor，進入了臨界區之後，如果發現線程繼續運作的條件沒有滿足，它則調用對象（一般就是被 synchronized 的對象）的 wait() 方法，放棄了 Monitor，進入 “Wait Set”隊列。隻有當别的線程在該對象上調用了 notify() 或者 notifyAll() ， “ Wait Set”隊列中線程才得到機會去競争，但是隻有一個線程獲得對象的Monitor，恢複到運作态。在 “Wait Set”中的線程， DUMP中表現為： in Object.wait()，類似于：

"Thread-1" prio=10 tid=0x08223250 nid=0xa in Object.wait() [0xef47a000..0xef47aa38]

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

- waiting on <0xef63beb8> (a java.util.ArrayList)

at java.lang.Object.wait(Object.java:474)

at testthread.MyWaitThread.run(MyWaitThread.java:40)

- locked <0xef63beb8> (a java.util.ArrayList)

at java.lang.Thread.run(Thread.java:595)

仔細觀察上面的 DUMP資訊，你會發現它有以下兩行：

² locked <0xef63beb8> (ajava.util.ArrayList)

² waiting on <0xef63beb8> (ajava.util.ArrayList)

這裡需要解釋一下，為什麼先 lock了這個對象，然後又 waiting on同一個對象呢？讓我們看看這個線程對應的代碼：

synchronized(obj){

.........

obj.wait();

.........

}

線程的執行中，先用 synchronized 獲得了這個對象的 Monitor（對應于 locked <0xef63beb8> ）。當執行到 obj.wait(), 線程即放棄了 Monitor的所有權，進入 “wait set”隊列（對應于 waiting on<0xef63beb8> ）。

往在你的程式中，會出現多個類似的線程，他們都有相似的 dump也可能是正常的。比如，在程式中有多個服務線程，設計成從一個隊列裡面讀取請求資料。這個隊列就是 lock以及 waiting on的對象。當隊列為空的時候，這些線程都會在這個隊列上等待，直到隊列有了資料，這些線程被notify，當然隻有一個線程獲得了 lock，繼續執行，而其它線程繼續等待。

JDK指令二、jstack(Java Stack Trace)

基本介紹

指令格式

案例

說明

案例1-使用

案例2-死鎖

生成死鎖（deadlock）的源代碼

用jstack進行分析和結果

繼續閱讀

MAT(Memory Analyzer Tool)工具之eclipse安裝

JVM新生代詳解

線上JVM Young GC調優

Minor GC、Major GC、Full GC以及Mixed GC之間的差別