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

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

jstack 命令的基本使用

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

# 最基本的使用
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 上:

"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)
...

阻塞在內置鎖上:

"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 的輸出內容作詳細梳理;

輸出內容的結構

首先還是要説一下 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 的第一行末尾, 一般情況下可分為如下幾類:

線程的狀態

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

線程的重要調用修飾

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 應用, 有一些通常都會存在的線程:

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 資源最高的線程;
首先我先介紹一下手工敲命令分析的方法:

# -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`

下面介紹一個腳本, 其功能是: 按照 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

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

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