Hatena::ブログ(Diary)

ablog このページをアンテナに追加 RSSフィード Twitter

2015-01-01

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

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

WebLogicスレッドダンプの見方については id:yamadamn さんの スレッドダンプから見るWebLogic Serverの世界 #javaee - yamadamnのはてな日記 がわかりやすい。

f:id:yohei-a:20150102164538p:image:w640


スレッドダンプとは


何の役に立つか

性能問題の原因調査
スレッドのクラッシュ時の原因調査
  • クラッシュすると、JVM は自動的にスレッドダンプをファイルに出力するので、どのメソッドの実行中にクラッシュしたかなどを調べることができるらしい。

取得方法

  • jstack、kill -3*4 <PID>(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 で取得できるらしいです。
$ 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 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=10Thread.MIN_PRIORITY(1): 最低優先度
Thread.NORM_PRIORITY(5): デフォルト
Thread.MAX_PRIORITY(10): 最高優先度
スレッドIDtid=0x00007f04e006c000JVMの世界のスレッドID
何度かスレッドダンプを取得したときはスレッドIDをキーにスレッドの状態遷移を追跡できる
ネイティブスレッドIDnid=0x5580OSスレッド(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 Serverトラブルシュートのノウハウより

P.22

f:id:yohei-a:20150102220647p:image:w360

P.23

f:id:yohei-a:20150102220646p:image:w360

P.25

f:id:yohei-a:20150102220645p:image:w360

P.26

f:id:yohei-a:20150102220643p:image:w360


付録

f:id:yohei-a:20150102221858p:image:w360

f:id:yohei-a:20150102221857p:image:w360

  • 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    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

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

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

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

*4:kill -QUIT でも同じ

*5:または標準エラー

スパム対策のためのダミーです。もし見えても何も入力しないでください
ゲスト


画像認証