1. 程式人生 > >[轉]通過jstack日誌分析和問題排查

[轉]通過jstack日誌分析和問題排查

簡介

jstack用於生成java虛擬機器當前時刻的執行緒快照。執行緒快照是當前java虛擬機器內每一條執行緒正在執行的方法堆疊的集合,生成執行緒快照的主要目的是定位執行緒出現長時間停頓的原因,如執行緒間死鎖、死迴圈、請求外部資源導致的長時間等待等。 執行緒出現停頓的時候通過jstack來檢視各個執行緒的呼叫堆疊,就可以知道沒有響應的執行緒到底在後臺做什麼事情,或者等待什麼資源。 如果java程式崩潰生成core檔案,jstack工具可以用來獲得core檔案的java stack和native stack的資訊,從而可以輕鬆地知道java程式是如何崩潰和在程式何處發生問題。另外,jstack工具還可以附屬到正在執行的java程式中,看到當時執行的java程式的java stack和native stack的資訊, 如果現在執行的java程式呈現hung的狀態,jstack是非常有用的。

一:jstack

jstack命令的語法格式: jstack 。可以用jps檢視java程序id。這裡要注意的是:

  1. 不同的 JAVA虛機的執行緒 DUMP的建立方法和檔案格式是不一樣的,不同的 JVM版本, dump資訊也有差別。

  2. 在實際執行中,往往一次 dump的資訊,還不足以確認問題。建議產生三次 dump資訊,如果每次 dump都指向同一個問題,我們才確定問題的典型性。

二:jstack Dump 日誌檔案中的執行緒狀態

1:dump 檔案裡,值得關注的執行緒狀態有


死鎖, Deadlock(重點關注) 

執行中,Runnable   

等待資源, Waiting on condition(重點關注) 

等待獲取監視器, Waiting on monitor entry(重點關注)

暫停,Suspended

物件等待中,Object.wait() 或 TIMED_WAITING

阻塞, Blocked(重點關注)  

停止,Parked


2:Dump檔案中的執行緒狀態含義及注意事項



Deadlock:死鎖執行緒,一般指多個執行緒呼叫間,進入相互資源佔用,導致一直等待無法釋放的情況。



Runnable:一般指該執行緒正在執行狀態中,該執行緒佔用了資源,正在處理某個請求,有可能正在傳遞SQL到資料庫執行,有可能在對某個檔案操作,有可能進行資料型別等轉換。



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

    如果發現有大量的執行緒都在處在 Wait on condition,從執行緒 stack看, 正等待網路讀寫,這可能是一個網路瓶頸的徵兆。因為網路阻塞導致執行緒無法執行。一種情況是網路非常忙,幾 乎消耗了所有的頻寬,仍然有大量資料等待網路讀 寫;另一種情況也可能是網路空閒,但由於路由等問題,導致包無法正常的到達。所以要結合系統的一些效能觀察工具來綜合分析,比如 netstat統計單位時間的傳送包的數目,如果很明顯超過了所在網路頻寬的限制 ; 觀察 cpu的利用率,如果系統態的 CPU時間,相對於使用者態的 CPU時間比例較高;如果程式執行在 Solaris 10平臺上,可以用 dtrace工具看系統呼叫的情況,如果觀察到 read/write的系統呼叫的次數或者執行時間遙遙領先;這些都指向由於網路頻寬所限導致的網路瓶頸。另外一種出現 Wait on condition的常見情況是該執行緒在 sleep,等待 sleep的時間到了時候,將被喚醒。





locked:執行緒阻塞,是指當前執行緒執行過程中,所需要的資源長時間等待卻一直未能獲取到,被容器的執行緒管理器標識為阻塞狀態,可以理解為等待資源超時的執行緒。



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

三:各種情況演示分享

分享dump日誌我們需要找到一個分析工具,一直沒找到好的分析工具後然我同事分享了我一個是IBM開發的工具叫

"IBM Thread and Monitor Dump Analyzer for Java" 下載地址:https://www.ibm.com/developerworks/community/groups/service/html/communityview?communityUuid=2245aa39-fa5c-4475-b891-14c205f7333c


1:Deadlock(死鎖)



演示程式碼

public class DiedsynchronizedTest {
public static void main(String[] args) {
Thread a = new ThreadRunA();
Thread b = new ThreadRunB();
a.start();
b.start();
}
}
class ThreadRunA extends Thread {
public void run() {
System.out.println(“================A===================”);
synchronized (A.A) {
System.out.println(“我要開始執行任務A。。。。” + Thread.currentThread().getName());
try {
Thread.sleep(5000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (B.B) {
}
System.out.println(“我在執行任務結束了A。。。。” + Thread.currentThread().getName() + “:” + B.B.hashCode() + “:”
+ A.A.hashCode());
}
}
}
class ThreadRunB extends Thread {
public void run() {
System.out.println(“================B===================”);
synchronized (B.B) {
System.out.println(“我要開始執行任務B。。。。” + Thread.currentThread().getName());
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (A.A) {
}
System.out.println(“我在執行任務結束了B。。。。” + Thread.currentThread().getName() + “:” + B.B + “:” + A.A);
}
}
}
class A {
static Integer A = new Integer(1);
}
class B {
static Integer B = new Integer(1);
}

這是個簡單的死迴圈的程式碼,我們用jstack命令dump他的資訊匯入分析工具如圖



從圖上能清醒的看到Thread-1和Thread-0現實 Deadlock,而且還幫你定位到了具體的類和行數。

所以我們在系統中實用鎖的時候,一定要考慮到多執行緒併發,避免出現交叉呼叫。


2:Runnable 


有時候我們發現CPU效能消耗很厲害,系統日誌也看不出什麼問題,那麼這個時候我們要堅持執行中的執行緒有沒有出現異常,

下面我們看下程式碼

public class DumpWhileDemo {
public static void main(String[] args) {
new Thread(new WhileThread()).start();
System.out.println();
}
}
class WhileThread implements Runnable {
@Override
public void run() {
while (true) {
System.out.println(“Thread”);
}
}
}

這段程式碼我們可以看出new一個執行緒,執行緒裡面是無線迴圈,執行main方法後,CPU會直線上升。可以通過linux的top命令看出來。

我們jstack命令dump它的資訊匯入檢視如下圖



我們能看到執行緒Thread-0的Method方法列顯示的是我們的自己寫的類,其他兩個run的的都顯示NO JAVA STACK.

如果我還是懷疑Thread-0方法那麼我多dump幾次檢視,如果依舊還是這樣那麼可以說明此訪問有問題。

因為我們使用jstack的時候列印的是當時的狀態,所以多列印幾次基本能確定是否是有異常方法.不要天真的認為Runnable狀態的就

沒問,一切皆有可能。


3:Waiting on monitor entry 和 in Object.wait()


這個我就直接拿我們線上出的故障來和大家分享下,當時我們分析的時候吧dump日誌下載到本地,然後匯入到工具裡面,看下圖





線上我們可以清楚的看到DubboServerHandler有200的執行緒(dubbo服務預設執行緒池就200,這個瞭解dubbo的同學都應該清楚),

我們再看右側報錯的內容backlog日誌出問題了,後面我開發同學進一步分析是dubbo日誌列印沒有控制執行緒數量。

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()”。

4、 Blocked  

還是上面說的那個故障,這個時候執行緒已經阻塞了看下圖,導致阻塞的原因就是就是200個預設執行緒一直沒有釋放或者,

等待進入的執行緒太多

總結

Java執行緒 DUMP的基本知識和分析的基本方法,並且解釋瞭如何利用執行緒的 DUMP資訊,以及結合作業系統的各種資源使用情況,

分析程式的效能問題,從而達到改程序序,提高效能的目的。