あなたとスレッドダンプ - スレッドダンプ入門 - この国では犬が が非常にわかりやすく、自分でブログエントリを書く必要はないが、Oracle Database や Linux の性能分析に携わる者の観点から Java のスレッドダンプについて整理してみた。具体的なスレッドダンプの分析方法はサポートエンジニアが語るWebLogic Serverトラブルシュートのノウハウがとてもわかりやすい。
WebLogic のスレッドダンプの見方については id:yamadamn さんの スレッドダンプから見るWebLogic Serverの世界 #javaee - yamadamnのはてな日記 がわかりやすい。
スレッドダンプとは
何の役に立つか
性能問題の原因調査
スレッドのクラッシュ時の原因調査
- クラッシュすると、JVM は自動的にスレッドダンプをファイルに出力するので、どのメソッドの実行中にクラッシュしたかなどを調べることができるらしい。
取得方法
- jstack、kill -3*4
(UNIX/Linux)、ctrl+Break(Windows)などで取得できる。 - トラブルシューティングでは kill -3 より、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 で取得できるらしいです。
$ jcmd 30759 sun.tools.jcmd.JCmd 30444 weblogic.Server $ jcmd 30444 Thread.print|head -10 30444: 2016-01-24 02:36:38 Full thread dump OpenJDK 64-Bit Server VM (24.79-b02 mixed mode): "Attach Listener" daemon prio=10 tid=0x00007f32b4001000 nid=0x77b2 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "[STANDBY] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00007f32e89e1800 nid=0x7710 in Object.wait() [0x00007f32d5edc000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method)
分析のコツ
- 時間をあけて複数回取得して推移を分析する
- 全てのスレッドの状態遷移がない→ハング
- スレッドの処理が少しずつ進んでいる→スローダウン
- 分析のコツは The TSA Method や Oracle Database の Acitve Session History の分析と近い気がする
- 侍とか Flight Recoder、ThreadLogic とか使うと可視化してくれるので楽そう
スレッドダンプの読み方
サンプル
"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をキーにスレッドの状態遷移を追跡できる |
| 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 のスレッドがいて、同じメソッドが実行されていると、犯人ぽいことがわかる |
| 状態（Weblogicの実行スレッドのみ） | [ACTIVE] | [ACTIVE]:スレッドがリクエストを実行中であるか、またはリクエストをすぐに実行できる状態 [STANDBY]:アクティブなスレッドプールから削除されていて、リクエストをすぐには処理できない状態 [STUCK]:リクエストを実行中だが、しばらく経っても完了していない状態 ※ACTIVEだからといって必ずしもリクエストを実行中な訳ではない。STANDBYでもなくアイドル状態にもなっていない場合は、リクエストを実行しているとみなすことができ、この詳細はJMX(管理コンソールなど)で確認できる。 |
ケーススタディ
サポートエンジニアが語るWebLogic Serverトラブルシュートのノウハウより
P.22
P.23
P.25
P.26
付録
- 16進数から10進数への変換(nid=0x5580の場合の例)
# 16進数→10進数 $ perl -e 'map{print hex($_)} @ARGV' 5580 21888 # 10進数→16進数 $ perl -e 'printf qq/%x/, 21888' 5580
参考
- スレッドダンプから見るWebLogic Serverの世界 #javaee - yamadamnのはてな日記
- jstack でスレッドダンプを取る - にょきにょきブログ
- スレッドダンプの森で覚えた死のロックへの違和感 (1/3)：現場から学ぶWebアプリ開発のトラブルハック（11） - ＠IT
- CUBRID blog - database management systems and software development
- Oracle Blogs | Oracle WebLogic Channel Blog
- スローダウン、ハングを一発解決 スレッドダンプはトラブルシューティングの味方 #wlstudy
- スレッドダンプの読み方
- Thread.State (Java Platform SE 7)
- 高負荷なのに片方のサーバにだけ余裕が……なぜ？ (3/4)：Linuxトラブルシューティング探偵団（1） - ＠IT
- http://www.acroquest.co.jp/webworkshop/JavaTroubleshooting/column_005Main.html
- はじめてのJava入門[スレッド(スレッドの優先順位)]
- Javaトラブルに応じた初動対応のまとめ - 見習いプログラミング日記
- http://samuraism.jp/diary/2006/09/21/1158846052527.html
- http://www.oracle.com/technetwork/jp/ondemand/middleware/application-grid/20100324-weblogic-trouble-255304-ja.pdf
- Linux perf Examples
おまけ
スレッドダンプをとってみた手順
- サンプルプログラム(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
$ 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 56 │52: 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
