jstack日志深入理解

在分析線上問題時常使用到jstack <PID>命令將當時Java應用程序的線程堆棧dump出來。

面對jstack 日志，我們如何查看？

 

首先要清楚線程的狀態

線程的狀態有：new、runnable、running、waiting、timed_waiting、blocked、dead

線程狀態變遷圖：

 

各狀態說明：

New: 當線程對象創建時存在的狀態，此時線程不可能執行；

Runnable：當調用thread.start()后，線程變成為Runnable狀態。只要得到CPU，就可以執行；

Running：線程正在執行；

Waiting：執行thread.join()或在鎖對象調用obj.wait()等情況就會進該狀態，表明線程正處於等待某個資源或條件發生來喚醒自己；

Timed_Waiting：執行Thread.sleep(long)、thread.join(long)或obj.wait(long)等就會進該狀態，與Waiting的區別在於Timed_Waiting的等待有時間限制；

Blocked：如果進入同步方法或同步代碼塊，沒有獲取到鎖，則會進入該狀態；

Dead：線程執行完畢，或者拋出了未捕獲的異常之后，會進入dead狀態，表示該線程結束

其次，對於jstack日志，我們要着重關注如下關鍵信息

Deadlock：表示有死鎖

Waiting on condition：等待某個資源或條件發生來喚醒自己。具體需要結合jstacktrace來分析，比如線程正在sleep，網絡讀寫繁忙而等待

Blocked：阻塞

Waiting on monitor entry：在等待獲取鎖

in Object.wait()：獲取鎖后又執行obj.wait()放棄鎖

對於Waiting on monitor entry 和 in Object.wait()的詳細描述：Monitor是 Java中用以實現線程之間的互斥與協作的主要手段，它可以看成是對象或者 Class的鎖。每一個對象都有，也僅有一個 monitor。從下圖中可以看出，每個 Monitor在某個時刻，只能被一個線程擁有，該線程就是 "Active Thread"，而其它線程都是 "Waiting Thread"，分別在兩個隊列 " Entry Set"和 "Wait Set"里面等候。在 "Entry Set"中等待的線程狀態是 "Waiting for monitor entry"，而在 "Wait Set"中等待的線程狀態是 "in Object.wait()"

 

1)blocked 的例子

 

程序先輸出main,在輸出thread，說明mian的線程是先獲得同步鎖的

執行jstack pid輸出信息如下：

 

 

可以看到thread1在進行等待獲取到鎖，此時進入waiting for monitor entry，並是阻塞狀態。

 

而main線程提前獲取到鎖，當由於調用了sleep此時進入到Timed_waiting狀態，此時man線程鎖住的對象地址是7f3167cf0，而thread1正在等待獲取這個鎖對象。

 

prio：線程的優先級

tid：線程id

nid:操作系統映射的線程id, 非常關鍵，后面再使用jstack時補充；

1103e9000

106692000 ：表示線程棧的起始地址。

 

 

從jstack日志中，可以看到：主線程獲取到thread2對象上的鎖，因此正在執行sleep操作，狀態為TIMED_WAINTING, 而thread2由於未獲取到thread2對象上的鎖，因此處於BLOCKED狀態。

再細看，thread2 正在"waiting to lock <7f3167cf0>"，即試圖在地址為7f3167cf0所在的對象獲取鎖，而該鎖卻被main線程占有（locked <7f3167cf0>）。main線程正在"waiting on condition"，說明正在等待某個條件觸發，由jstacktrace來看，此線程正在sleep。

經驗：如果在jstack日志發現大量的線程在waiting to lock 某個地址，只要能查到哪個線程獲取到鎖就可以方便定位問題了

 

 

2）object.wait();

   public static void main(String[] args) {
        final Thread thread = new Thread() {
            @Override
            public void run() {
                synchronized (this) {
                    System.out.println(Thread.currentThread().getName());
                    try {
                        wait();
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
        };
        thread.start();
        thread.setName("zouxh");//起名字，方便在線程棧里面進行查看
        try {
            TimeUnit.SECONDS.sleep(3);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        synchronized (thread) {
            System.out.println(Thread.currentThread().getName());
            try {
                TimeUnit.SECONDS.sleep(30);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            thread.notify();
        }
    }

　　

執行后，查看jstack的日志如下：

"zouxh" prio = 5 tid = 7f e18c97b800 nid = 0x115e58000 in Object.wait()[115e57000]
java.lang.Thread.State:WAITING(on object monitor)
at java.lang.Object.wait(Native Method)
        - waiting on< 7f 3112f e8 > (a jstat.MainWati$1)
at java.lang.Object.wait(Object.java:485)
at jstat.MainWati$1.run(MainWati.java:16)
-locked < 7f 3112f e8 > (a jstat.MainWati$1)


"main" prio = 5 tid = 7f e18c000800 nid = 0x10c47b000 waiting on condition[10 c47a000]
java.lang.Thread.State:TIMED_WAITING(sleeping)
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:300)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:328)
at jstat.MainWati.main(MainWati.java:37)
-locked < 7f 3112f e8 > (a jstat.MainWati$1)

 

可以看到由於調用了object.wait()方法的時候放棄了鎖，所以zouxh這個線程就出現了object.wait()狀態，線程的狀態就是waiting，等待notify來進行喚醒。

 

 

由於mian線程在獲得zouxh的線程鎖后，調用了sleep方法，所以此時進入了wating on condition等待某一個資源，進入到time_waiting狀態。

 

3）waiting on conditon

  private static BlockingQueue<String> blockingQueue = new ArrayBlockingQueue<String>(1);
        public static void main (String[]args){
            blockingQueue.add("zouxh");
            try {
　　　　　　　　//阻塞的添加
                blockingQueue.put("ssss");
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }

 

線程棧如下：

"main" prio=5 tid=7f8f65000800 nid=0x10d7bb000 waiting on condition [10d7ba000]

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

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

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

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)

at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:257)

at jstat.WatingTest.main(WatingTest.java:13)

 

此時main線程進入了waiting on conditon狀態，等待某一個資源，此時可以看到是在

a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObjec進行了等待，阻塞住了，這是由於put發生了阻塞。

 

 

總結：

 

對於jstack日志，我們要着重關注如下關鍵信息

Deadlock：表示有死鎖

Waiting on condition：等待某個資源或條件發生來喚醒自己。具體需要結合jstacktrace來分析，比如線程正在sleep，網絡讀寫繁忙而等待

Blocked：阻塞

Waiting on monitor entry：在等待獲取鎖

 

如果說系統慢，那么要特別關注Blocked,Waiting on condition

如果說系統的cpu耗的高，那么肯定是線程執行有死循環，那么此時要關注下Runable狀態。