3、jdk工具之jstack(Java Stack Trace)

時間 2020-06-08

標籤 jdk 工具 jstack java stack trace 欄目 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%。

jps -l 確認一下，31951就是博客的進程ID，或 cat /proc/31951/cmdline 看下進程的啓用命令。

root@iZ94dcq8q6jZ:~# jps -l
28416 sun.tools.jps.Jps
31951 blog.jar

top -Hp 31951 以線程模式查看下進程31951的全部線程狀況

假設想看下第二個線程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進行分析和結果

在dos中輸入命令：jstack 7404

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都指向同一個問題，咱們才肯定問題的典型性。

二、命令格式

$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之間關係，以及線程的狀態轉換圖：

從圖中能夠看出，每一個 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，繼續執行，而其它線程繼續等待。

dump:

Dump的本意是"傾卸垃圾"、"把(垃圾桶)倒空"。在計算機技術中使用Dump的主要意思仍然如此,即當電腦運行發現故障後,沒法排除而死機,一般要從新啓動。爲了找出故障的緣由 ,須要分析現場(即死機時整個內存的當前情況),在從新啓動系統以前要把內存中的一片0、 1(這時它們尤如一堆垃圾)"卸出"保存起來,以便由專家去分析引發死機的緣由。技術資料中把這個"卸出"的過程叫dump;有時把卸出的"內容"也叫dump。國際標準化組織(ISO)把前者定義爲To record,at a particular instant,the contents of all or part of one stora geevice in another storage device.Dumping is usually for the purpose of debuggin。"譯文以下:"在某個特定時刻,把一個存儲設備中的所有或部分的內容轉錄進另外一個存儲設備之中。轉儲的目的一般是用於排除故障。"所以,dump做爲動詞,宜譯爲"轉儲";相應的動名詞,或做爲名詞來看 ,則譯爲"轉儲(過程、動做…)"。同時,ISO把後者定義爲"Data that as been dumped。"譯文以下:"經轉儲而產生的那些數據"。這些數據實際上就是內存中由一片0、1組成的map(映像),所以,這時的dump應譯爲"內像"(內存中的映像)。
明白了dump的上述二個基本含義以後,dump的其它用法就不難理解了。好比在IBM主機系統中作dump時,一般是轉儲到磁帶上,因此有人把這盤磁帶也叫dump!爲了便於閱讀與分析,把內像按既定的格式打印在紙上,人們便把這一堆打印紙也叫dump!爲了實現以上二項工做,必須有相應的程序,人們把這種程序也叫dump,實爲dump routine的簡寫。IBM的VSE/SP操做系統中還專門有一條dump宏指令供程序員使用。
當咱們把dump譯爲"轉儲"時,老是指"把內存中的內容複製到其它存儲設備上",而實際使用dump時,並不是一概如此,有時dump就是copy(複製)的意思。IBM的《Dictionary of Compuing》(第十版)就是這樣定義dump的:"To copy data in a readable format from mainr a uxiliary storage onto a external medium such as tape,diskette orprinter(按照可閱讀的格式,把主存或輔存中的數據複製到外部媒體,如磁帶、軟盤或打印機上。)","Tocopy the contents of all or part of virtual storage for the purpose of collectng error information(爲了收集出錯信息把部分或所有虛存中的內容複製起來)。"最明顯的例子是VM/SP(IBM的大型操做系統)中有一個DDR(DASD Dump Restore:磁盤轉儲恢復)獨立程序,主用於把可運行的操做系統等軟件從磁盤(DASD)複製到磁帶上(這個過程稱爲dump,或反過來,在無需操做系統的控制下 ,可把磁帶上的軟件複製回到磁盤之中,以便恢復可運行的操做系統(這個過程爲restore)。這兒的dump過程就不涉及內存,相似的例子還有很多這兒就不一一列舉了。在影像系統中,dump被定義爲一種方法或過程(process),藉此數字節目代碼能夠從錄像盤傳送播放錄像的微處理器上,這時的dump就是"轉錄"的意思。一樣在影像系統中,dump還被定義爲:一次可裝入播放錄像處理器中的"一段節目代碼(a unit of program code)",一張錄像盤上能夠存放多個節目段(program dumps)。除上述的意思外,dump有時還表示:"切斷[掉](計算機)電源"