天天看點

jstack日志深入了解

在分析線上問題時常使用到jstack <PID>指令将當時Java應用程式的線程堆棧dump出來。 面對jstack 日志,我們如何檢視?

首先要清楚線程的狀态 線程的狀态有: new、runnable、running、waiting、timed_waiting、blocked、dead 線程狀态變遷圖:

jstack日志深入了解

各狀态說明: 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()"

jstack日志深入了解

1) blocked 的例子

jstack日志深入了解

程式先輸出main,在輸出thread,說明mian的線程是先獲得同步鎖的 執行jstack pid輸出資訊如下:

jstack日志深入了解
jstack日志深入了解

可以看到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) { // TODO Auto-generated catch block e.printStackTrace(); } } } }; thread.start(); thread.setName("zouxh");//起名字,友善線上程棧裡面進行檢視 try { TimeUnit.SECONDS.sleep(3); } catch (InterruptedException e) { // TODO Auto-generated catch block e.printStackTrace(); } synchronized (thread) { System.out.println(Thread.currentThread().getName()); try { TimeUnit.SECONDS.sleep(30); } catch (InterruptedException e) { // TODO Auto-generated catch block e.printStackTrace(); } thread.notify(); } } 執行後,檢視jstack的日志如下: "zouxh" prio=5 tid=7fe18c97b800 nid=0x115e58000 in Object.wait() [115e57000]    java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <7f3112fe8> (a jstat.MainWati$1) at java.lang.Object.wait(Object.java:485) at jstat.MainWati$1.run(MainWati.java:16) - locked <7f3112fe8> (a jstat.MainWati$1)

"main" prio=5 tid=7fe18c000800 nid=0x10c47b000 waiting on condition [10c47a000]    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 <7f3112fe8> (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) { // TODO Auto-generated catch block 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狀态。