前段事件公司出現了一個嚴重故障(調用dubbo服務一直處於超時,整個服務系統發生雪崩,系統徹底訪問不了),一開始怎么都找不到問題的根源,日志的表現形式是dubbo線程池用完了,那么具體是什么導致的沒有找到,后然通過jstack日志分析才找到問題的根源,根源就是系統日志代碼寫有問題。通過這個故障我們來了解下如何通過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 <pid>。可以用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 {
-
-
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信息,以及結合操作系統的各種資源使用情況,
分析程序的性能問題,從而達到改進程序,提高性能的目的。