jstack 命令使用經驗總結和執行緒性能診斷腳本

2020 年 4 月 8 日
筆記

編輯：業餘草來源：https://www.xttblog.com/?p=4946

分享一下，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 執行緒的性能診斷帶來幫助, 如需幫助，可以加我Wx：codedq，免費獲得「執行緒性能診斷的輔助腳本」和 Shell 影片教程。

//|-----執行緒名------| |-執行緒創建次序-| |是否守護進程| |---執行緒優先順序---| |-------執行緒 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) 或者 TIMEDWAITING (on object monitor), 這種一般與執行緒動作 in Object.wait() [0x…] 一起出現, 並且執行緒調用棧的最末端調用方法為 at java.lang.Object.wait(Native Method), 以表示 object.wait() 方法的調用; 另外, WAITING 與 TIMEDWAITING 的區別在於是否設置了超時中斷, 即 wait(long timeout) 與 wait() 的區別;
WAITING (parking) 或者 TIMEDWAITING (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 與 TIMEDWAITING 的區別與第三點中提到的原因一致;

執行緒的重要調用修飾

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 優化作決策依據;

主執行緒 main通常 main 執行緒是 jvm 創建的 1 號用戶執行緒, 有了 main 之後才有了後來的其他用戶執行緒;

Reference Handler 執行緒與 Finalizer 執行緒這兩個執行緒用於虛擬機處理 override 了 Object.finalize() 方法的實例, 對實例回收前作最後的判決。

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

使用程式碼作 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 一一對應的 (只是十進位與十六進位的區別), 所以便可以拿轉換得到的十六進位 threadid0x, 去 thread dump 中搜索對應的 nid, 定位問題執行緒。

#!/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

該腳本的主要功能是: 按照 cpu 使用率從高到低排序, 列印指定 jvm 進程的前 n 個執行緒。

不懂 shell 的，可以後台回復「shell」獲取影片教程。

thread dump 可視化分析工具

dump 可視化工具比較多，這裡推薦兩個我常用的。gceasy.io 和 fastthread.io。