Javaのスレッドダンプの読み方

あなたとスレッドダンプ - スレッドダンプ入門 - この国では犬がコードを書いています が非常にわかりやすく、自分でブログエントリを書く必要はないが、Oracle Database や Linux の性能分析に携わる者の観点から Java のスレッドダンプについて整理してみた。具体的なスレッドダンプの分析方法はサポートエンジニアが語るWebLogic Serverトラブルシュートのノウハウがとてもわかりやすい。
WebLogic のスレッドダンプの見方については id:yamadamn さんの スレッドダンプから見るWebLogic Serverの世界 #javaee - yamadamnのはてな日記 がわかりやすい。

スレッドダンプとは

  • Javaのスレッドのスナップショット。
  • 取得した瞬間のJava仮想マシン(JVM)内に存在するスレッド(ID、名前、状態、タイプなど)とコールスタックを見ることができる。
  • OSで言うと、ps -eflL*1 + 各スレッドの pstack(コールスタック)みたいなイメージ
  • Oracle Database で言うと、V$SESSION + 各セッションの oradebug shortstack みたいなイメージ*2

何の役に立つか

性能問題の原因調査
  • 処理が遅い時に”誰待ち”か調べる
    • どのスレッドのどのメソッドがロックを確保していて(犯人)、どのスレッドのどのメソッドでそのロック解放を待っているか(被害者)
    • システムコールや割込み待ち時間が長く、JVMより下のレイヤーのOSやハードウェアの処理時間が長く(犯人)、JVM内のスレッドは待たされているか(被害者)
  • CPU使用率が高い時にどのスレッドのどのメソッドがCPUを使っているか調べる。
    • この場合は top -Hc*3を合わせて見るとよい。
スレッドのクラッシュ時の原因調査
  • クラッシュすると、JVM は自動的にスレッドダンプをファイルに出力するので、どのメソッドの実行中にクラッシュしたかなどを調べることができるらしい。

取得方法

  • jstack、kill -3*4 (UNIX/Linux)、ctrl+Break(Windows)などで取得できる。
  • トラブルシューティングでは kill -3 より、jstack のほうが使いやすいと思う。
    • kill -3 だとJVMのプロセスの標準出力*5に出力されるが、jstack だと jstack の標準出力に出力されるため。
  • 取得手順例
# jps でpidを調べて、jstack で取得する
$ jps
21567 Jps
21083 Counter
$ jstack 21083
# ps で PID を調べて、kill -3(-QUITでも同じ)で取得する
$ ps auxw|grep [j]ava
yazekats 21083  0.0  0.0 5411796 14924 pts/0   Sl+  15:36   0:00 java Counter
$ kill -3 21083
  • Java 7u4 HotSpot では jcmd で取得できるらしいです。

分析のコツ

  • 時間をあけて複数回取得して推移を分析する
    • 全てのスレッドの状態遷移がない→ハング
    • スレッドの処理が少しずつ進んでいる→スローダウン
  • 分析のコツは The TSA MethodOracle Database の Acitve Session History の分析と近い気がする
  • とか Flight RecoderThreadLogic とか使うと可視化してくれるので楽そう

スレッドダンプの読み方

サンプル
"Reference Handler" daemon prio=10 tid=0x00007f04e006c000 nid=0x5580 in Object.wait() [0x00007f04da4e5000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007adc85190> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:503)
	at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
	- locked <0x00000007adc85190> (a java.lang.ref.Reference$Lock)
フォーマット
スレッド名 prio=優先度 tid=スレッドID nid=ネイティブスレッドID 状態 スタックアドレス
   java.lang.Thread.State: 状態
      スタックトレース1
      スタックトレース2
      ...
各項目の説明
項目 説明
スレッド名 Reference Handler 以下のようなものがある
-CompilerThread
-Finalizer
-Reference Handler
-VM Thread
Weblogicの場合
-weblogic.socket.Muxer[n] : ソケットリーダースレッド
-weblogic.kernel.Default[n] : 実行スレッド
-DynamicListenThread[Default] : リスンスレッド
タイプ daemon ユーザスレッドとデーモンスレッドの2種類がある。
例えば、JVMのガベージコレクタはデーモンスレッド
優先度 prio=10 Thread.MIN_PRIORITY(1): 最低優先度
Thread.NORM_PRIORITY(5): デフォルト
Thread.MAX_PRIORITY(10): 最高優先度
スレッドID tid=0x00007f04e006c000 JVMの世界のスレッドID
何度かスレッドダンプを取得したときはスレッドIDをキーにスレッドの状態遷移を追跡できる
ネイティブスレッドID nid=0x5580 OSのスレッド(LWP)番号の16進数表現
10進数に変換すると、ps -elfL のLWP列や top -Hc のPID列と紐づけできる
nid=0x5580 なら 5580 を10進数に変換すると 21888
状態 java.lang.Thread.State: WAITING (on object monitor) NEW:起動していない
RUNNABLE:CPUで実行中(OSのランキューに入っている状態)
BLOCKED:ブロックされ、モニターロックを待機している
WAITING:ほかのスレッドが特定のアクションを実行するのを無期限に待機している
TIMED_WAITING:指定された待機時間、ほかのスレッドがアクションを実行するのを待機している
スタックトレース at java.lang.Object.wait(Native Method)
- waiting on <0x00000007adc85190> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
- locked <0x00000007adc85190> (a java.lang.ref.Reference$Lock)
-一番上が処理中のメソッドで、下は呼出し元のメソッド
-ロックを保持しているスレッドと待機しているスレッドがずっと同じなら、あるスレッドがロックを解放しないため、他のスレッドが延々待っていてハングしている
-ロックを保持しているスレッドと待機しているスレッドがいるが、ロック保持スレッドと待機スレッドが常に変っている場合は、延々待っているわけではないが、共有リソースで競合が発生してスローダウンしている
-CPU使用率が高い場合は、常に状態が RUNNABLE のスレッドがいて、同じメソッドが実行されていると、犯人ぽいことがわかる
付録


  • 16進数から10進数への変換(nid=0x5580の場合の例)
# 16進数→10進数
$ perl -e 'map{print hex($_)} @ARGV' 5580
21888
# 10進数→16進数
$ perl -e 'printf qq/%x/, 21888'
5580

おまけ

スレッドダンプをとってみた手順
  • サンプルプログラム(Counter.java)
import java.lang.*;

public class Counter
{
    public static void main(String[]args)
    {
        int i;

        for (i = 0; i <= 1000; i++)
        {
	    try {
               Thread.sleep(1000);
            } catch(InterruptedException e) {
               e.printStackTrace();
            }
        }
        System.out.println("finished.");
    }
}
$ javac Counter.java
  • 実行する
$ java Counter &
[1] 23198
  • スレッドダンプを取得する
$ jps
23212 Jps
23198 Counter
$ jstack 23198
2015-01-02 16:49:16
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.65-b04 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f9770001000 nid=0x5acf runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" daemon prio=10 tid=0x00007f97a0094800 nid=0x5aaa runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007f97a0092800 nid=0x5aa9 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007f97a008f800 nid=0x5aa8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007f97a008d000 nid=0x5aa7 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007f97a006e800 nid=0x5aa6 in Object.wait() [0x00007f9796e69000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007adc85608> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(Unknown Source)
	- locked <0x00000007adc85608> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(Unknown Source)
	at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

"Reference Handler" daemon prio=10 tid=0x00007f97a006c000 nid=0x5aa5 in Object.wait() [0x00007f9796f6a000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007adc85190> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:503)
	at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
	- locked <0x00000007adc85190> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00007f97a0008800 nid=0x5a9f waiting on condition [0x00007f97a573d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at Counter.main(Counter.java:12)

"VM Thread" prio=10 tid=0x00007f97a0068000 nid=0x5aa4 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f97a001e000 nid=0x5aa0 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f97a0020000 nid=0x5aa1 runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007f97a0021800 nid=0x5aa2 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007f97a0023800 nid=0x5aa3 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f97a009f800 nid=0x5aab waiting on condition 

JNI global references: 106
jstackって起動にちょっと時間かかる?

jstackって起動にちょっと時間かからない?気のせい?

jstackって起動にちょっと時間かからない?気のせい? - eerga のコメント / はてなブックマーク

少しだけ調べて見ました。以下はあくまで一例で、その時の状況によって実行時間は変わると思います。

  • jstack は実行可能ファイル
$ ls -l `which jstack`
lrwxrwxrwx 1 root root 24 Dec  8 18:08 /usr/bin/jstack -> /etc/alternatives/jstack
$ ls -l /etc/alternatives/jstack
lrwxrwxrwx 1 root root 49 Dec  8 18:08 /etc/alternatives/jstack -> /usr/lib/jvm/java-1.6.0-openjdk.x86_64/bin/jstack
$ file /usr/lib/jvm/java-1.6.0-openjdk.x86_64/bin/jstack
/usr/lib/jvm/java-1.6.0-openjdk.x86_64/bin/jstack: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked (uses shared libs), for GNU/Linux 2.6.18, stripped
  • 61% が ON CPU でうち 88% が%user、39%が OFF CPU
$ time jstack 5977
(中略)
real	0m0.386s
user	0m0.209s
sys	0m0.028s
  • ライブラリコールは pthread_join での所要時間が88%。1回しかコールしていないのに所要時間が長い、
$ ltrace -c jstack 5977
% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 88.27    0.483246      483246         1 pthread_join
  2.96    0.016188         183        88 fgets
  2.44    0.013374       13374         1 dlopen
  0.73    0.004014         167        24 JLI_StringDup
  0.63    0.003429         171        20 strcspn
  0.61    0.003344         167        20 strspn
  0.53    0.002885         144        20 JLI_MemAlloc
  0.43    0.002339         116        20 strlen
  0.34    0.001866         155        12 getenv
  0.28    0.001515         137        11 sprintf
  0.26    0.001439         130        11 strrchr
  0.25    0.001364          71        19 strncmp
  0.18    0.001005          71        14 strcat
  0.15    0.000798         114         7 JLI_MemFree
  0.15    0.000795         198         4 access
  0.14    0.000759         759         1 pthread_attr_destroy
  0.13    0.000736         184         4 
  0.11    0.000613         153         4 cap_free
  0.09    0.000515         103         5 strchr
  0.09    0.000510          63         8 strcmp
  0.09    0.000496         248         2 fclose
  0.08    0.000454         227         2 fopen
  0.08    0.000442         221         2 readlink
  0.08    0.000437         218         2 cap_get_proc
  0.07    0.000392         196         2 getuid
  0.07    0.000388         194         2 __xstat
  0.07    0.000387         129         3 strncpy
  0.07    0.000374         187         2 geteuid
  0.07    0.000373         186         2 getgid
  0.07    0.000371         185         2 cap_init
  0.07    0.000370         370         1 pthread_create
  0.07    0.000369         184         2 getegid
  0.06    0.000315         157         2 cap_compare
  0.06    0.000313         156         2 JLI_FreeManifest
  0.05    0.000299         149         2 fflush
  0.05    0.000296         148         2 strcpy
  0.03    0.000159         159         1 putenv
  0.03    0.000155          77         2 dlsym
  0.01    0.000076          76         1 pthread_attr_init
  0.01    0.000069          69         1 getpid
  0.01    0.000058          58         1 pthread_attr_setdetachstate
  0.01    0.000058          58         1 pthread_attr_setstacksize
  0.01    0.000058          58         1 memcpy
------ ----------- ----------- --------- --------------------
100.00    0.547443                   334 total
  • システムコールは futex での所要時間が96%。1回当たりの所要時間が長いので、futexによる排他制御での待機で時間を要しているのか?
$ strace -c jstack 5977
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 96.33    0.013998        2333         6         2 futex
  2.95    0.000429         215         2           execve
  0.34    0.000049           0       101        78 open
  0.25    0.000036           7         5           munmap
  0.13    0.000019           1        22           read
  0.00    0.000000           0        23           close
  0.00    0.000000           0        30        21 stat
  0.00    0.000000           0        23           fstat
  0.00    0.000000           0        60           mmap
  0.00    0.000000           0        33           mprotect
  0.00    0.000000           0         6           brk
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         2           rt_sigprocmask
  0.00    0.000000           0         6         4 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         4           readlink
  0.00    0.000000           0         2           getrlimit
  0.00    0.000000           0         2           getuid
  0.00    0.000000           0         2           getgid
  0.00    0.000000           0         2           geteuid
  0.00    0.000000           0         2           getegid
  0.00    0.000000           0         6           capget
  0.00    0.000000           0         2           arch_prctl
  0.00    0.000000           0         2           set_tid_address
  0.00    0.000000           0         2           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.014531                   350       105 total
  • perf でプロファイリング
$ sudo echo 0 > /proc/sys/kernel/perf_event_paranoid
$ perf record -F 99 jstack 5977
(中略)
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.021 MB perf.data (~905 samples) ]
$ perf report
Samples: 81  of event 'cycles:HG', Event count (approx.): 2444132237
37.43%  jstack  libpthread-2.12.so  [.] pthread_getspecific ★この行を選択
26.19%  jstack  libjvm.so           [.] 0x00000000007ff8c1
19.25%   :6106  [kernel.kallsyms]   [k] zap_pte_range
10.18%  jstack  [kernel.kallsyms]   [k] acl_permission_check
 3.84%  jstack  perf-6106.map       [.] 0x00007efff100fc87
 1.36%  jstack  libverify.so        [.] 0x0000000000009c06
 1.28%  jstack  [vdso]              [.] 0x00007fff21796891
 0.08%  jstack  [kernel.kallsyms]   [k] finish_task_switch
 0.04%  jstack  [kernel.kallsyms]   [k] down_write
 0.04%  jstack  [kernel.kallsyms]   [k] perf_event_context_sched_in
 0.04%  jstack  [kernel.kallsyms]   [k] audit_syscall_exit
 0.04%  jstack  [kernel.kallsyms]   [k] perf_pmu_enable
 0.04%  jstack  [kernel.kallsyms]   [k] sysret_careful
 0.04%  jstack  [kernel.kallsyms]   [k] sysret_signal
 0.03%  jstack  [kernel.kallsyms]   [k] schedule_tail
 0.03%  jstack  [kernel.kallsyms]   [k] ret_from_fork
 0.03%   :6106  [kernel.kallsyms]   [k] intel_pmu_enable_all
 0.02%  jstack  [kernel.kallsyms]   [k] __perf_event_task_sched_in
 0.02%  jstack  [kernel.kallsyms]   [k] x86_pmu_enable
 0.01%  jstack  [kernel.kallsyms]   [k] native_write_msr_safe

Annotate pthread_getspecific ★この行を選択
Zoom into jstack(6106) thread
Zoom into libpthread-2.12.so DSO
Browse map details
Exit

       │    Disassembly of section .text:
       │
       │    0000003ba6a0c690 <__pthread_getspecific>:
100.00 │      cmp    $0x1f,%edi
       │      push   %rbx
       │    ↓ ja     4a
       │      mov    %edi,%eax
       │      shl    $0x4,%rax                                                                        
       │      mov    %fs:0x10,%rdx
       │      lea    0x310(%rdx,%rax,1),%rdx
       │1d:   mov    0x8(%rdx),%rax
       │      test   %rax,%rax
       │    ↓ je     3c
       │      mov    %edi,%edi
       │      lea    __GI___pthread_keys,%rcx
       │      shl    $0x4,%rdi
       │      mov    (%rcx,%rdi,1),%rbx
       │      cmp    %rbx,(%rdx)
       │    ↓ jne    3e
       │3c:   pop    %rbx
       │    ← retq
       │3e:   movq   $0x0,0x8(%rdx)
       │      xor    %eax,%eax
       │      pop    %rbx
       │    ← retq
       │4a:   cmp    $0x3ff,%edi
       │    ↓ jbe    5652:   xor    %eax,%eax
       │      pop    %rbx
       │    ← retq
       │56:   mov    %edi,%edx
       │      shr    $0x5,%edx
       │      mov    %fs:0x510(,%rdx,8),%rdx
       │      test   %rdx,%rdx
       │   │↑ je     52
       │   │  mov    %rdi,%rax
       │   │  and    $0x1f,%eax
       │   │  shl    $0x4,%rax
       │   │  add    %rax,%rdx
       │   └──jmp    1d

*1:-Lオプションでスレッド単位で表示される

*2:もしくは systemstate dump をとても簡素にしたもの

*3:Linuxの場合、Solaris なら prstat、AIX なら topas、Windows ならタスクマネージャーや Process Explorer

*4:kill -QUIT でも同じ

*5:または標準エラー