多一份經驗，少一次踩坑！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 的第三部分線程調用棧中, 一般會把與鎖相關的資源使用狀態以附加的形式作重點修飾, 這與線程的動作及狀態有着密切的聯繫, 一般情況下可分為如下幾類:

這是因為該線程之前獲得過該內置鎖, 現在因為 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。