多一份經驗，少一次踩坑！jstack 命令使用經驗總結

這是Bella醬的第 46 期分享java

做者 | zshellzhangnode

來源 | http://dwz.date/bebzlinux

jstack 在命令使用上十分簡潔, 然而其輸出的內容卻十分豐富, 信息量足, 值得深刻分析;
以往對於 jstack 產生的 thread dump, 我不多字斟句酌得分析過每一部分細節, 針對 jstack 的性能診斷也沒有一個模式化的總結; 今天這篇文章我就來詳細整理一下與 jstack 相關的內容。

jstack 命令的基本使用

jstack 在命令使用上十分簡潔, 其信息量與複雜度主要體如今 thread dump 內容的分析上;
web

# 最基本的使用
sudo -u xxx jstack {vmid}
# 從 core dump 中提取 thread dump
sudo -u xxx jstack core_file_path
# 除了基本輸出外, 額外展現 AbstractOwnableSynchronizer 鎖的佔有信息
# 可能會消耗較長時間
sudo -u xxx jstack -l {vmid}

jstack 輸出內容結構分析

首先展現幾段 thread dump 的典型例子:
正在 RUNNING 中的線程:面試

"elasticsearch[datanode-39][[xxx_index_v4][9]: Lucene Merge Thread #2403]" #45061 daemon prio=5 os_prio=0 tid=0x00007fb968213800 nid=0x249ca runnable [0x00007fb6843c2000]
   java.lang.Thread.State: RUNNABLE
        ...
        at org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:94)
        at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:626)

阻塞在 java.util.concurrent.locks.Condition 上:
shell

"DubboServerHandler-10.64.16.66:20779-thread-510" #631 daemon prio=5 os_prio=0 tid=0x00007fb6f4ce5800 nid=0x1743 waiting on condition [0x00007fb68ed2f000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000e2978ef0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        ...

阻塞在內置鎖上:
apache

"qtp302870502-26-acceptor-0@45ff00a-ServerConnector@63475ace{HTTP/1.1}{0.0.0.0:9088}" #26 prio=5 os_prio=0 tid=0x00007f1830d3a800 nid=0xdf64 waiting for monitor entry [0x00007f16b5ef9000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:234)
        - waiting to lock <0x00000000c07549f8> (a java.lang.Object)
        at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:377)
        ...
        at java.lang.Thread.run(Thread.java:745)

"JFR request timer" #6 daemon prio=5 os_prio=0 tid=0x00007fc2f6b1f800 nid=0x18070 in Object.wait() [0x00007fb9aa96b000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00007fba6b50ea38> (a java.util.TaskQueue)
        at java.lang.Object.wait(Object.java:502)
        at java.util.TimerThread.mainLoop(Timer.java:526)
        - locked <0x00007fba6b50ea38> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:505)

以上展現了四個線程的 jstack dump, 有 running 狀態, 也有阻塞狀態, 覆蓋面廣, 具備典型性; 下面來對 jstack 的輸出內容做詳細梳理;api

輸出內容的結構瀏覽器

首先仍是要說一下 jstack 輸出的內容結構, 就以上方舉的第四個線程爲例:
如下是第一部份內容, 記錄了線程的一些基本信息, 從左到右每一個元素的含義已經以註釋標註在元素上方; 其中比較重要的是 nid, 它是 java 線程與操做系統的映射, 在 linux 中它和與其對應的輕量級進程 pid 相同 (須要十六進制與十進制轉換), 這將爲基於 java 線程的性能診斷帶來幫助, 詳細請見本文後面段落 #線程性能診斷的輔助腳本;
微信

//|-----線程名------| |-線程建立次序-| |是否守護進程| |---線程優先級---| |-------線程 id-------| |-所映射的linux輕量級進程id-| |-------------線程動做--------------|
  "JFR request timer" #6              daemon        prio=5 os_prio=0  tid=0x00007fc2f6b1f800 nid=0x18070                 in Object.wait() [0x00007fb9aa96b000]

如下是第二部份內容, 表示線程當前的狀態;

java.lang.Thread.State: WAITING (on object monitor)

如下是第三部份內容, 主要記錄了線程的調用棧; 其中比較重要的是一些關鍵調用上的 #動做修飾, 這些爲線程死鎖問題的排查提供了依據;

at java.lang.Object.wait(Native Method)
- waiting on <0x00007fba6b50ea38> (a java.util.TaskQueue)
at java.lang.Object.wait(Object.java:502)
at java.util.TimerThread.mainLoop(Timer.java:526)
- locked <0x00007fba6b50ea38> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

線程的動做

線程動做的記錄在每一個 thread dump 的第一行末尾, 通常狀況下可分爲以下幾類:

runnable, 表示線程在參與 cpu 資源的競爭, 可能在被調度運行也可能在就緒等待;
sleeping, 表示調用了 Thread.sleep(), 線程進入休眠;
waiting for monitor entry [0x...], 表示線程在試圖獲取內置鎖, 進入了等待區 Entry Set, 方括號內的地址表示線程等待的資源地址;
in Object.wait() [0x...], 表示線程調用了 object.wait(), 放棄了內置鎖, 進入了等待區 Wait Set, 等待被喚醒, 方括號內的地址表示線程放棄的資源地址;
waiting on condition [0x...], 表示線程被阻塞原語所阻塞, 方括號內的地址表示線程等待的資源地址; 這種和 jvm 的內置鎖體系沒有關係, 它是 jdk5 以後的 java.util.concurrent 包下的鎖機制;

線程的狀態

線程的狀態記錄在每一個 thread dump 的第二行, 並以 java.lang.Thread.State 開頭, 通常狀況下可分爲以下幾類:

RUNNABLE, 這種通常與線程動做 runnable 一塊兒出現;
BLOCKED (on object monitor), 這種通常與線程動做 waiting for monitor entry 一塊兒出現, 不過在其線程調用棧最末端並無一個固定的方法, 由於 synchronized 關鍵字能夠修飾各類方法或者同步塊;
WAITING (on object monitor) 或者 TIMED_WAITING (on object monitor), 這種通常與線程動做 in Object.wait() [0x...] 一塊兒出現, 而且線程調用棧的最末端調用方法爲 at java.lang.Object.wait(Native Method), 以表示 object.wait() 方法的調用;
另外, WAITING 與 TIMED_WAITING 的區別在因而否設置了超時中斷, 即 wait(long timeout) 與 wait() 的區別;
WAITING (parking) 或者 TIMED_WAITING (parking), 這種通常與線程動做 waiting on condition [0x...] 一塊兒出現, 而且線程調用棧的最末端調用方法通常爲 at sun.misc.Unsafe.park(Native Method);
Unsafe.park 使用的是線程阻塞原語, 主要在 java.util.concurrent.locks.AbstractQueuedSynchronizer 類中被使用到, 不少基於 AQS 構建的同步工具, 如 ReentrantLock, Condition, CountDownLatch, Semaphore 等都會誘發線程進入該狀態;
另外, WAITING 與 TIMED_WAITING 的區別與第三點中提到的緣由一致;

線程的重要調用修飾

thread dump 的第三部分線程調用棧中, 通常會把與鎖相關的資源使用狀態以附加的形式做重點修飾, 這與線程的動做及狀態有着密切的聯繫, 通常狀況下可分爲以下幾類:

locked <0x...>, 表示其成功獲取了內置鎖, 成爲了 owner;
parking to wait for <0x...>, 表示其被阻塞原語所阻塞, 一般與線程動做 waiting on condition 一塊兒出現;
waiting to lock <0x...>, 表示其在 Entry Set 中等待某個內置鎖, 一般與線程動做 waiting for monitor entry 一塊兒出現;
waiting on <0x...>, 表示其在 Wait Set 中等待被喚醒, 一般與線程動做 in Object.wait() [0x...] 一塊兒出現;
另外, waiting on 調用修飾每每與 locked 調用修飾一同出現, 如以前列舉的第四個 thread dump:

at java.lang.Object.wait(Native Method)
  - waiting on <0x00007fba6b50ea38> (a java.util.TaskQueue)
  at java.lang.Object.wait(Object.java:502)
  at java.util.TimerThread.mainLoop(Timer.java:526)
  - locked <0x00007fba6b50ea38> (a java.util.TaskQueue)
  at java.util.TimerThread.run(Timer.java:505)

這是由於該線程以前得到過該內置鎖, 如今由於 object.wait() 又將其放棄了, 因此在調用棧中會出現前後兩個調用修飾;

死鎖檢測的展現

在 jdk5 以前, Doug Lea 大神尚未發佈 java.util.concurrent 包, 這個時候說起的鎖, 就僅限於 jvm 監視器內置鎖; 此時若是進程內有死鎖發生, jstack 將會把死鎖檢測信息打印出來:

Found one Java-level deadlock:
=============================
"Thread-xxx":
  waiting to lock monitor 0x00007f0134003ae8 (object 0x00000007d6aa2c98, a java.lang.Object),
  which is held by "Thread-yyy"
"Thread-yyy":
  waiting to lock monitor 0x00007f0134006168 (object 0x00000007d6aa2ca8, a java.lang.Object),
  which is held by "Thread-xxx"

Java stack information for the threads listed above:
===================================================
"Thread-xxx":
    ...
"Thread-yyy":
    ...
Found 1 deadlock.

然然後來 Doug Lea 發佈了 java.util.concurrent 包, 當談及 java 的鎖, 除了內置鎖以外還有了基於 AbstractOwnableSynchronizer 的各類形式; 因爲是新事物, 彼時 jdk5 的 jstack 沒有及時提供對以 AQS 構建的同步工具的死鎖檢測功能, 直到 jdk6 才完善了相關支持;

常見 java 進程的 jstack dump 特徵

首先, 不論是什麼類型的 java 應用, 有一些一般都會存在的線程:

VM Thread 與 VM Periodic Task Thread
虛擬機線程, 屬於 native thread, 凌駕於其餘用戶線程之上;
VM Periodic Task Thread 一般用於虛擬機做 sampling/profiling, 收集系統運行信息, 爲 JIT 優化做決策依據;

C1 / C2 CompilerThread
虛擬機的 JIT 及時編譯器線程:

"C1 CompilerThread2" #10 daemon prio=9 os_prio=0 tid=0x00007feb34114000 nid=0x18b2 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #9 daemon prio=9 os_prio=0 tid=0x00007feb34112000 nid=0x18b1 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #8 daemon prio=9 os_prio=0 tid=0x00007feb3410f800 nid=0x18b0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

Reference Handler 線程與 Finalizer 線程

這兩個線程用於虛擬機處理 override 了 Object.finalize() 方法的實例, 對實例回收前做最後的判決;

Reference Handler 線程用於將目標對象放入 reference queue:

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f91e007f000 nid=0xa80 in Object.wait() [0x...]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
        - locked <0x00000000c0495140> (a java.lang.ref.Reference$Lock)

Finalizer 線程用於從 reference queue 中取出對象以執行其 finalize 方法:

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f91e0081000 nid=0xa81 in Object.wait() [0x...]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        - locked <0x00000000c008db88> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

GC 線程
這塊對於不一樣的 gc 收集器選型有各自不一樣的線程狀態 (線程數視 cpu 核心數而定);

# Parallel Scavenge
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f91e0021000 nid=0xa7a runnable 
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f91e0023000 nid=0xa7b runnable

# ParNew
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007feb3401e800 nid=0x18a4 runnable 
"Gang worker#1 (Parallel GC Threads)" os_prio=0 tid=0x00007feb34020000 nid=0x18a5 runnable

# CMS
"Concurrent Mark-Sweep GC Thread" os_prio=0 tid=0x00007feb34066800 nid=0x18a8 runnable

# G1
"G1 Main Concurrent Mark GC Thread" os_prio=0 tid=0x00007fc2f4091800 nid=0x1805e runnable

"Gang worker#0 (G1 Parallel Marking Threads)" os_prio=0 tid=0x00007fc2f4093800 nid=0x1805f runnable 
"Gang worker#1 (G1 Parallel Marking Threads)" os_prio=0 tid=0x00007fc2f4095800 nid=0x18060 runnable

"G1 Concurrent Refinement Thread#0" os_prio=0 tid=0x00007fc2f4079000 nid=0x1805d runnable 
"G1 Concurrent Refinement Thread#1" os_prio=0 tid=0x00007fc2f4077000 nid=0x1805c runnable

以上即是 java 進程裏一般都會存在的線程;

使用代碼做 thread dump

除了使用 jstack 以外, 還有其餘一些方法能夠對 java 進程做 thread dump, 若是將其封裝爲 http 接口, 即可以不用登錄主機, 直接在瀏覽器上查詢 thread dump 的狀況;
使用 jmx 的 api

public void  threadDump() {
   ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
   for (ThreadInfo threadInfo : threadMxBean.dumpAllThreads(true, true)) {
       // deal with threadInfo.toString()
   }
}

使用 Thread.getAllStackTraces() 方法

public void threadDump() {
    for (Map.Entry<Thread, StackTraceElement[]> stackTrace : Thread.getAllStackTraces().entrySet()) {
        Thread thread = (Thread) stackTrace.getKey();
        StackTraceElement[] stack = (StackTraceElement[]) stackTrace.getValue();
        if (thread.equals(Thread.currentThread())) {
            continue;
        }
        // deal with thread
        for (StackTraceElement stackTraceElement : stack) {
            // deal with stackTraceElement
        }
    }
}

線程性能診斷的輔助腳本

使用 jstack 還有一個重要的功能就是分析熱點線程: 找出佔用 cpu 資源最高的線程;
首先我先介紹一下手工敲命令分析的方法:

使用 top 命令找出 cpu 使用率高的 thread id:

# -p pid: 只顯示指定進程的信息
# -H: 展現線程的詳細信息
top -H -p {pid}
# 使用 P 快捷鍵按 cpu 使用率排序, 並記錄排序靠前的若干 pid (輕量級進程 id)

做進制轉換:

         # 將記錄下的十進制 pid 轉爲十六進制
thread_id_0x=`printf "%x" $thread_id`
`echo "obase=16; $thread_id" | bc`

因爲 thread dump 中記錄的每一個線程的 nid 是與 linux 輕量級進程 pid 一一對應的 (只是十進制與十六進制的區別), 因此即可以拿轉換獲得的十六進制 thread_id_0x, 去 thread dump 中搜索對應的 nid, 定位問題線程;

下面介紹一個腳本, 其功能是: 按照 cpu 使用率從高到低排序, 打印指定 jvm 進程的前 n 個線程;

#!/bin/sh

default_lines=10
top_head_info_padding_lines=8
default_stack_lines=15

jvm_pid=$1
jvm_user=$2
((thread_stack_lines=${3:-$default_lines}+top_head_info_padding_lines))

threads_top_capture=$(top -b -n1 -H -p $jvm_pid | grep $jvm_user | head -n $thread_stack_lines)
jstack_output=$(echo "$(sudo -i -u $jvm_user jstack $jvm_pid)")
top_output=$(echo "$(echo "$threads_top_capture" | perl -pe 's/\e\[?.*?[\@-~] ?//g' | awk '{gsub(/^ +/,"");print}' | awk '{gsub(/ +|[+-]/," ");print}' | cut -d " " -f 1,9 )\n ")

echo "***********************************************************"
uptime
echo "Analyzing top $top_threads threads"
echo "***********************************************************"

printf %s "$top_output" | while IFS= read line
do
    pid=$(echo $line | cut -d " " -f 1)
    hexapid=$(printf "%x" $pid)
    cpu=$(echo $line | cut -d " " -f 2)
    echo -n $cpu "% [$pid] "
    echo "$jstack_output" | grep "tid.*0x$hexapid " -A $default_stack_lines | sed -n -e '/0x'$hexapid'/,/tid/ p' | head -n -1
done

該腳本有多種版本, 在我司的每臺主機上的指定路徑下都存放了一個副本; 出於保密協議, 該腳本源碼不便於公開, 上方所展現的版本是基於美團點評的技術專家王銳老師在一次問答分享中給出的代碼所改造的;

thread dump 可視化分析工具

與 gceasy.io 一道, 同出自一家之手: fastthread.io。

-END-

2.服務端高併發分佈式架構演進之路

3.平滑遷移 Dubbo 服務的思考

4.15分鐘理解KD樹

5.Redis用過嗎？用過。那講一講跳躍表Skip list吧

6.Hystrix原理與實戰

若是你喜歡本文

請長按二維碼，關注 Bella的技術輪子

轉發至朋友圈，是對我最大的支持

喜歡就點個在看吧

本文分享自微信公衆號 - Bella的技術輪子（wheel_of_bella）。
若有侵權，請聯繫 support@oschina.cn 刪除。
本文參與「OSC源創計劃」，歡迎正在閱讀的你也加入，一塊兒分享。