1. 程式人生 > >ThreadDump分析筆記(一) 解讀堆疊

ThreadDump分析筆記(一) 解讀堆疊

1. 概述

隨著系統日益增大,程式碼結構日漸複雜,經過驗收測試的系統可能在實際生產環境下表現的一塌糊塗,也可能非常棒。因此通過QA並不能保證系統不會發生記憶體洩漏,往往流量越大洩露的越快,最後導致系統崩潰。比如在某個時間點系統一直出現TimeOut、或者系統突然處理速度急劇下降等問題。對於開發人員就非常棘手了,很多人根本一頭霧水,基本上就是拍腦袋瞎猜了。其實發現此類問題定位的技術主要有記憶體洩漏定位、執行緒堆疊分析等。

執行緒堆疊概述

執行緒堆疊也就是所謂的執行緒呼叫棧(都是獨立的),在Java執行緒堆疊式JVM執行緒狀態的一個瞬時快照,快照包含了當前時刻所有執行緒的執行狀態,包括每一個執行緒的呼叫棧,鎖的持有等資訊。每個虛擬機器都提供了Thread Dump的後門幫助我們匯出堆疊資訊。藉助執行緒堆疊會幫助我們迅速地縮小問題的範圍, 找到突破口, 命中目標 。

執行緒堆疊一般包含的資訊:
1、執行緒名字,ID,執行緒的數量
2、執行緒執行狀態、鎖的狀態(鎖被哪個執行緒持有,哪個執行緒在等待)
3、函式呼叫層級關係。包括了完整類名,方法名,原始碼行數

執行緒堆疊資訊的多少,依賴於你係統的複雜度,藉助堆疊資訊,可分析很多問題,如執行緒死鎖、鎖競爭、死迴圈、識別耗時操作等。在多執行緒場景下進行穩定問題分析和效能分析他是最有效的方法,多數情況甚至無需瞭解系統就可以進行相應分析。

當然,執行緒堆疊也不是萬能的,因為其是瞬時快照,所以對已消失沒有留下痕跡的資訊,是無法追蹤歷史的。這種情況只能藉助於監控系統和日誌進行分析。如連線池中的連線被哪些執行緒使用了沒有被釋放這類問題。其實也就是說執行緒堆疊分析的都是非功能性的問題。

執行緒堆疊善於分析以下問題:
1、系統無緣無故CPU過高
2、系統掛起,無響應
3、系統執行越來越慢
4、執行緒死鎖、死迴圈、餓死等。
5、由於執行緒數量太多導致系統失敗(如無法建立執行緒等)

輸出堆疊
1、unix/Linux 使用kill -3 pid 進行轉儲
2、可以使用VisualVM等直接檢視轉儲
3、JDK1.5以上的可以使用Thread.getStackTrace() 控制堆疊自動列印

2. 關於執行緒

只有實際操作了你才能更加的理解其概念,上一個DEMO

/**
 * Created by QIANG on 2017/9/29
 */
public class
ThreadTest {
Object obj1 = new Object(); Object obj2 = new Object(); public void fun1(){ synchronized (obj1){ fun2(); } } public void fun2(){ synchronized (obj2){ while (true){ System.out.println("我要一直跑跑跑。。。"); } } } public static void main(String[] args){ ThreadTest aa = new ThreadTest(); aa.fun1(); } }

這裡我是用VisualVM 列印執行緒堆疊,在完整的堆疊資訊中我們可以看到各種系統執行緒,限於篇幅原因只留下我關注的資訊


2017-10-19 10:46:09
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.144-b01 mixed mode):  
"main" #1 prio=5 os_prio=0 tid=0x0000000002737000 nid=0x5d1c runnable [0x000000000270f000]
  java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked <0x0000000081e1c728> (a java.io.BufferedOutputStream)
        at java.io.PrintStream.write(PrintStream.java:482)
        - locked <0x0000000081e1c0a0> (a java.io.PrintStream)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
        at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
        - locked <0x0000000081e1c058> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
        at java.io.PrintStream.write(PrintStream.java:527)
        - eliminated <0x0000000081e1c0a0> (a java.io.PrintStream)
        at java.io.PrintStream.print(PrintStream.java:669)
        at java.io.PrintStream.println(PrintStream.java:806)
        - locked <0x0000000081e1c0a0> (a java.io.PrintStream)
        at com.ecej.test.Thread.ThreadTest.fun2(ThreadTest.java:21)
        - locked <0x0000000081e0a300> (a java.lang.Object)
        at com.ecej.test.Thread.ThreadTest.fun1(ThreadTest.java:14)
        - locked <0x0000000081e1c0c0> (a java.lang.Object)
        at com.ecej.test.Thread.ThreadTest.main(ThreadTest.java:28)
  Locked ownable synchronizers:
        - None
"VM Thread" os_prio=2 tid=0x0000000017928800 nid=0x3160 runnable 
"VM Periodic Task Thread" os_prio=2 tid=0x000000001a2d8000 nid=0x3dac waiting on condition 

執行緒堆疊是從下往上看,藉助這些資訊當前系統做了什麼就一目瞭然了。從main執行緒堆疊看出, - locked <0x0000000081e1c0c0> (a java.lang.Object) 這句代表該執行緒已經佔有鎖,鎖ID為0x0000000081e1c0c0,這個ID是系統自動生成的,只需要知道每次列印堆疊同一ID表示同一個鎖就行了。

分析下堆疊第一行資訊
“main” (執行緒名字)#1 prio=5(執行緒優先順序) os_prio=0 tid=0x0000000002737000(執行緒ID) nid=0x5d1c(執行緒對應本地執行緒ID) runnable(執行緒狀態) [0x000000000270f000](執行緒佔用記憶體地址)

nid=0x5d1c(執行緒對應本地執行緒ID) 這個大家看的有點懵逼,因為java我們開啟一個執行緒就必然對應JVM中一個本地執行緒,也就是說本地執行緒數和java執行緒堆疊執行緒數相同。
在linux下我們可以使用以下方式:
1. 使用ps -ef | grep java 獲得Java程序ID。
2. 使用pstack 獲得Java虛擬機器的本地執行緒的堆疊6。

如獲得Thread 8 (Thread 4067802000 (LWP 3356)),其中Thread 4067802000 (LWP 3356)都是表示為本地執行緒ID。這裡LWP 就對應了ThreadDump中的nid(native thread id ),只是nid用的是16進製表示的。分析得知,java執行緒和本地執行緒是同一個東西,本地執行緒才是真正的執行緒實體。

繼續分析標識,其中“runable”表示當前執行緒處於執行狀態。這個runable標識只能表示在JVM中此執行緒處於執行狀態,熟悉執行緒的同學一定知道,此狀態不代表真的在消耗PU。處於Runable的執行緒只能說明該執行緒沒有被阻塞在java的wait\sleep上,也沒有等待在鎖上。但如果該執行緒呼叫了本地方法,而本地方法處於等待狀態,那JVM是不知道原生代碼中發生了什麼,儘管當前執行緒實際處於阻塞狀態,但實際顯示出來的還是runable狀態,這種情況不消耗CPU。看個例子:

java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)

在實際中socket的本地方法大多數時間是阻塞的,除非緩衝區有資料。因此我們在分析哪個執行緒在消耗大量CPU時, 不能以這個”runnable”字樣作為判斷該執行緒是否消耗CPU的依據。
我們常線上程堆疊中發現”.init”或者”.clinit”字樣的函式, 比如下面得資訊
at java.util.logging.LogManager.<clinit>(LogManager.java:156)

.<clinit>”表示當前正在執行類的初始化。“<init>”正在執行物件得建構函式。下面說下兩種初始化:

類初始化:編譯器把類的變數初始化語句和型別得靜態初始化器都收集到cllinit方法內,只能由JVM呼叫並保證執行緒安全。再初始化前必須保證其超類已經被初始化。

並非所有的類都會擁有一個<clinit>() 方法, 在以下條件中該類不會擁有<client>() 方法:
• 該類既沒有宣告任何類變數, 也沒有靜態初始化語句;
• 該類聲明瞭類變數, 但沒有明確使用類變數初始化語句或靜態初始化語句初始化;
• 該類僅包含靜態final 變數的類變數初始化語句, 並且類變數初始化語句是編譯時常量表達式

說白話一點就是類是初始化靜態變數的,final static 直接進常量池了,不在此步驟。這一階段其實就是類載入的最後一階段。物件的初始化是代表了此物件生命週期的開始,只是呼叫了構造方法包括其裡面的內容。

3. 關於鎖

在進行堆疊解讀前再瞭解下鎖的基本常識,大家都知道wait()\sleep()的重大區別吧。相同點就是都釋放CPU,不同點就是wait()釋放鎖而sleep()不釋放。

從上邊例子的堆疊資訊可以看出鎖的重要資訊:
1、當一個執行緒佔有一個鎖時,執行緒堆疊會列印 - locked <0x0000000081e06858> (a java.io.InputStreamReader)
2、當一個執行緒正在等待其它執行緒釋放該鎖, 執行緒堆疊中會列印—waiting to lock <0x0000000081e06858>
3、當一個執行緒佔有一個鎖, 但又執行到該鎖的wait()上, 執行緒堆疊中首先列印locked,然後又會列印—waiting on <0x0000000081e06858>

從解讀中可以看出鎖有三個重要的特徵字:locked,waiting to lock,waiting on,瞭解這三個特徵字, 就能夠對鎖進行分析了 。大多數是有一個 -—waiting to lock就必然有一個locked,當然有時候你也會找不到locked,因為一個執行緒釋放鎖和另一個執行緒被喚醒有一個空窗期,這時候轉儲就會發生此種情況。

4. 關於狀態

藉助堆疊可以分析很多型別問題,CPU消耗分析是堆疊的一個重要內容,先看下java的執行緒流轉圖(圖來源於網路)

執行緒狀態流轉

下面說下堆疊中的執行緒狀態

RUNABLE 從JVM來說,此狀態就是執行緒正在執行,但是咧,實際上他不一定消耗CPU,有可能是正在進行網路IO,此時執行緒大多數是被掛起的,只有當資料到達後,執行緒才會重新被喚醒,掛起發生在原生代碼(Native)中,JVM其實根本就不知道(可不是呼叫wait/sleep)。

來個例子,下面的堆疊表示了當前程式正在從網路讀取資料。

Thread-39" daemon prio=1 tid=0x08646590 nid=0x666d runnable [5beb7000..5beb88b8]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)

下面這個堆疊表示了執行緒實實在在的在消耗CPU

"Thread-444" prio=1 tid=0xa4853568 nid=0x7ade runnable [0xafcf7000..0xafcf8680]
java.lang.Thread.State: RUNNABLE
at org.apache.commons.collections.ReferenceMap.getEntry(Unknown Source)
at org.apache.commons.collections.ReferenceMap.get(Unknown Source)

TIMED_WAITING(on object monitor) 表示當前執行緒被掛起一段時間,正在執行obj.wait(int time)方法

"JMX server connection timeout 16" #16 daemon prio=5 os_prio=0 tid=0x000000001a59f000 nid=0x5a74 in Object.wait() [0x000000001b7df000]
  java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000081f218e0> (a [I)
        at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
        - locked <0x0000000081f218e0> (a [I)
        at java.lang.Thread.run(Thread.java:748)

TIMED_WAITING(sleeping) 表示當前執行緒被掛起一段時間,即正在執行Thread.sleep(intt ime)方法

"Comm thread" daemon prio=10 tid=0x00002aaad4107400 nid=0x649f waiting on condition
[0x000000004133b000..0x000000004133ba00]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.hadoop.mapred.Task$1.run(Task.java:282)
at java.lang.Thread.run(Thread.java:619)

TIMED_WAITING(parking) 當前執行緒被掛起一段時間,即正在執行Thread.sleep(int time)方法 ,就是執行本地方法的sleep

"RMI TCP" daemon prio=6 tid=0x0ae3b800 nid=0x958 waiting on condition [0x17eff000..0x17effa94]
java.lang.Thread.State: TIMED_WAITING (parking )

WAINTING(on object monitor) 當前執行緒被掛起, 即正在執行obj.wait()方法
(無引數的wait()方法)

"IPC Client" daemon prio=10 tid=0x00002aaad4129800 nid=0x649d in Object.wait() [0x039000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

SO,處於TIMED_WAITING、 WAINTING狀態的執行緒一定不消耗CPU. 處於RUNNABLE的執行緒, 要結合當前執行緒程式碼的性質判斷, 是否消耗CPU.
• 如果是純Java運算程式碼, 則消耗CPU.
• 如果是網路IO,很少消耗CPU.
• 如果是原生代碼, 結合原生代碼的性質判斷(可以通過pstack/gstack獲取本地執行緒堆疊),如果是純運算程式碼, 則消耗CPU, 如果被掛起, 則不消耗CPU,如果是IO,則不怎麼消耗CPU。

小結:此次從執行緒、鎖、狀態這三方面做了基礎概念的筆記整理,下面將結合實際問題進行分析。

狍狍的日常生活