スレッドダンプには、Javaプロセスの各スレッドの情報(スタックトレース形式)が含まれているため、ハングアップやデッドロックなどの動作具合を調査することができます。
スレッドダンプの出力先は、標準出力です。スレッドダンプが出力される契機および出力先を、“表10.8 スレッドダンプの出力契機と出力先”に示します。
プログラムの種類 | 出力契機 | 出力先 |
|---|---|---|
Java EE 7 アプリケーション
| 一定の条件を満たした場合、コンテナの機能により自動的に採取される場合と利用者の任意のタイミングで手動による採取があります。
| 標準出力、JavaVMの出力をロギングしているファイル |
上記以外のJavaプログラム | 利用者の任意のタイミングで手動で採取することができます。
| コンソール(標準出力) |
注意
“-Xrs”オプションが指定されたJavaプロセスの場合、当該プロセスへ送られた[Ctrl]+[Break]キー押下またはQUITシグナルに対する動作は、OSのデフォルト動作になります。
そのため、“-Xrs”オプションを指定したJavaプロセスに対して[Ctrl]+[Break]キー押下またはQUITシグナルが送られると、当該Javaプロセスは強制終了または異常終了します。
スレッドダンプを出力する可能性があるJavaプロセスに対して、“-Xrs”オプションは指定しないでください。
ただし、Windows(R)でサービスとして登録されるJavaプロセスの場合は、“-Xrs”オプションを指定しない場合、ログオフ時に強制終了してしまいます。これが不都合な場合は、“-Xrs”オプションを指定してください。
以下のサンプルプログラムをもとにして、スレッドダンプの解析方法を説明します。
J2EEアプリケーション
1 :public class DeadlockSample {
2 : static boolean flag;
3 : static Thread1 thread1;
4 : static Thread2 thread2;
5 :
6 : public static void main(String[] args) {
7 : thread1 = new Thread1();
8 : thread2 = new Thread2();
9 : thread1.start();
10: thread2.start();
11: }
12:}
13:
14:class Thread1 extends Thread {
15: public Thread1(){
16: super("Thread1");
17: }
18:
19: public void run(){
20: synchronized(this){
21: System.out.println("Thread1開始");
22: while(DeadlockSample.flag==false){ // Thread2が開始するのを待つ
23: yield();
24: }
25: DeadlockSample.thread2.method();
26: notify();
27: }
28: }
29:
30: public synchronized void method(){
31: try{wait(1000);}catch(InterruptedException ex){}
32: System.out.println("Thread1.method()終了");
33: }
34:}
35:
36:class Thread2 extends Thread {
37: public Thread2(){
38: super("Thread2");
39: }
40:
41: public void run() {
42: synchronized(this){
43: DeadlockSample.flag = true;
44: System.out.println("Thread2開始");
45: DeadlockSample.thread1.method();
46: notify();
47: }
48: }
49:
50: public synchronized void method() {
51: try{wait(1000);}catch(InterruptedException ex){}
52: System.out.println("Thread2.method()終了");
53: }
54:}サンプルでは、Thread1とThread2がお互いに排他処理を行っています。
このサンプルを実行すると、次のように処理が進められます。
Thread1で、Thread1のロックを獲得する(20行目のsynchronized節)
Thread2で、Thread2のロックを獲得する(42行目のsynchronized節)
Thread1で、Thread2.method()を実行しようとして、ロック解放待ちになる(50行目のsynchronized修飾子)
Thread2で、Thread1.method()を実行しようとして、ロック解放待ちになる(30行目のsynchronized修飾子)
この結果、Thead1とThread2がお互いに、解放されないロックを待ち続けるデッドロック状態になります。
デッドロック状態で、スレッドダンプを採取したものを、以下に示します。
スレッドダンプ
"DestroyJavaVM" prio=5 tid=0x002856c8 nid=0x5f4 waiting on condition [0..6fad8] "Thread2" prio=5 tid=0x0092f4d8 nid=0x640 waiting for monitor entry [182ef000..182efd64] at Thread1.method(DeadlockSample.java:31) - waiting to lock <0x1002ffe8> (a Thread1) at Thread2.run(DeadlockSample.java:45) - locked <0x10030ca0> (a Thread2) "Thread1" prio=5 tid=0x0092f370 nid=0x294 waiting for monitor entry [182af000..182afd64] at Thread2.method(DeadlockSample.java:51) - waiting to lock <0x10030ca0> (a Thread2) at Thread1.run(DeadlockSample.java:25) - locked <0x1002ffe8> (a Thread1) "Signal Dispatcher" daemon prio=10 tid=0x0098eb80 nid=0x634 waiting on condition [0..0] "Finalizer" daemon prio=9 tid=0x0092a540 nid=0x5e8 in Object.wait() [1816f000..1816fd64] at java.lang.Object.wait(Native Method) - waiting on <0x10010498> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111) - locked <0x10010498> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x0096da70 nid=0x5e4 in Object.wait() [1812f000..1812fd64] at java.lang.Object.wait(Native Method) - waiting on <0x10010388> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:429) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115) - locked <0x10010388> (a java.lang.ref.Reference$Lock) "VM Thread" prio=5 tid=0x0096c950 nid=0x624 runnable "VM Periodic Task Thread" prio=10 tid=0x0092c008 nid=0x2a0 waiting on condition "Suspend Checker Thread" prio=10 tid=0x0098e118 nid=0x478 runnable Found one Java-level deadlock: ============================= "Thread2": waiting to lock monitor 0x00929c3c (object 0x1002ffe8, a Thread1), which is held by "Thread1" "Thread1": waiting to lock monitor 0x00929c5c (object 0x10030ca0, a Thread2), which is held by "Thread2" Java stack information for the threads listed above: =================================================== "Thread2": at Thread1.method(DeadlockSample.java:31) - waiting to lock <0x1002ffe8> (a Thread1) at Thread2.run(DeadlockSample.java:45) - locked <0x10030ca0> (a Thread2) "Thread1": at Thread2.method(DeadlockSample.java:51) - waiting to lock <0x10030ca0> (a Thread2) at Thread1.run(DeadlockSample.java:25) - locked <0x1002ffe8> (a Thread1) Found 1 deadlock.
解析方法
スレッドダンプの各スレッドの情報は、スタックトレース形式です。
Thread1とThread2の両方のスタックトレースには、“locked”と“waiting to lock”があります。また、スレッドダンプの下の方にも、“deadlock”の文字列があり、デットロックが発生していることが確認できます。
このように、スレッドダンプで全スレッドの動作状況を確認するにより、Javaプロセスがハングアップしているか、あるいは、デッドロック状態かを確認することができます。特に、短い間隔で複数のスレッドダンプを採取し、スレッドに動きがなければ、ハングアップの可能性があります。
スレッドダンプの詳細は、“トラブルシューティング集”も参照してください。
オブジェクトをロックしているスレッドがスレッドダンプ上に出ない
通常スレッドダンプ上のあるスレッドで次のように表示される場合があります。
- waiting to lock <オブジェクトID> (a クラス名)
このような場合、別のスレッドがそのオブジェクトIDのロックを持っていて、そのスレッドのトレース上のどこかで次の表示がされています。
- locked <オブジェクトID> (a クラス名)
しかし、スレッドダンプを表示するタイミングによっては“- locked <オブジェクトID> (a クラス名)”の表示がどのスレッドにも現われず、“- waiting to lock <オブジェクトID> (a クラス名)”だけ表示される場合があります。
以下のプログラムを例とします。
1 class NoLockOwner extends Thread
2 {
3 static Object lock = new Object();
4
5 public static void main(String[] arg)
6 {
7 new NoLockOwner().start();
8 new NoLockOwner().start();
9 }
10
11 public void run()
12 {
13 while (true) {
14 synchronized (lock) {
15 dumb();
16 }
17 }
18 }
19
20 void dumb()
21 {
22 int n = 0;
23 for (int i = 0 ; i < 1000 ; ++i)
24 n += i;
25 }
26
27 }(0) スレッドダンプを取ると、通常はこのようになります。
"Thread-1" prio=1 tid=0x10 nid=0x5 waiting for monitor entry [0x3000..0x4000]
at NoLockOwner.run(NoLockOwner.java:14)
- waiting to lock <0x800> (a java.lang.Object)
"Thread-0" prio=1 tid=0x20 nid=0x6 runnable [0x5000..0x6000]
at NoLockOwner.dumb(NoLockOwner.java:23)
at NoLockOwner.run(NoLockOwner.java:15)
- locked <0x800> (a java.lang.Object)(1) 先頭フレームでオブジェクトをロックしている場合は“- locked”ではなく、“- waiting to lock”と表示されることがあります。
"Thread-1" prio=1 tid=0x10 nid=0x5 waiting for monitor entry [0x3000..0x4000]
at NoLockOwner.run(NoLockOwner.java:14)
- waiting to lock <0x800> (a java.lang.Object)
"Thread-0" prio=1 tid=0x20 nid=0x6 runnable [0x5000..0x6000]
at NoLockOwner.run(NoLockOwner.java:14)
- waiting to lock <0x800> (a java.lang.Object)この場合、スレッドの状態を見て、runnableであれば、ロック待ちではなく、ロック取得後同じフレームを実行中の状態であると考えます。
Thread-0、Thread-1ともに、“- waiting to lock <0x800> (a java.lang.Object)”と表示されているので、どちらもロック待ちのように見えます。
しかし、Thread-0の状態は、runnbleなので、ロック待ち状態ではありません。
(2) “- waiting to lock”と表示されるのは、ロック待ちの状態だけではなく、ロック獲得処理の最中でもそのように表示されます。
"Thread-1" prio=1 tid=0x10 nid=0x5 waiting for monitor entry [0x3000..0x4000]
at NoLockOwner.run(NoLockOwner.java:14)
- waiting to lock <0x800> (a java.lang.Object)
"Thread-0" prio=1 tid=0x20 nid=0x6 waiting for monitor entry [0x5000..0x6000]
at NoLockOwner.run(NoLockOwner.java:14)
- waiting to lock <0x800> (a java.lang.Object)Thread-0、Thread-1ともに、“- waiting to lock <0x800> (a java.lang.Object)”と表示されているので、どちらもロック待ちのように見えます。
さらに、スレッドの状態も、どちらも、“waiting for monitor entry”になっています。
“- waiting to lock”と表示されるのは、ロック待ちの状態だけではなく、ロック獲得処理の最中でもそのように表示されます。
したがって、この場合、Thread-0またはThread-1のどちらか一方、あるいは両方がロック獲得処理の最中であると考えます。
しかし、この状態は長く続かず、短時間で(0)または(1)に移行します。
(3) ロックを開放した直後の状態
"Thread-1" prio=1 tid=0x10 nid=0x5 waiting for monitor entry [0x3000..0x4000]
at NoLockOwner.run(NoLockOwner.java:14)
- waiting to lock <0x800> (a java.lang.Object)
"Thread-0" prio=1 tid=0x20 nid=0x6 runnable [0x5000..0x6000]
at NoLockOwner.run(NoLockOwner.java:16)Thraed-0がちょうどロックを開放した直後の状態です。
この状態も長く続くとはなく、短時間で(0)または(1)に移行します。
スレッドダンプからアプリケーションの状態を判断する場合、ひとつのスレッドダンプから状態を判断することは困難です。
適切な判断をするためには、複数回のスレッドダンプを総合的に見ることが必要です。
スレッドダンプ中に表示されるsynchronizedメソッドの行番号について
次のようなプログラムを考えます。
1 class SyncMethod extends Thread
2 {
3 static volatile int k;
4
5 public static void main(String[] arg)
6 {
7 new SyncMethod().start();
8 }
9
10 public void run()
11 {
12 while (true) {
13 dumb();
14 }
15 }
16
17 synchronized void dumb()
18 {
19 /*
20 meaningless comments
21 */
22 int i = 0;
23 for ( ; i < 10 ; ++i)
24 k += i;
25 }
26
27 }このようなプログラムのスレッドダンプを取ると以下のように出力されることがあります。
"Thread-0" prio=1 tid=0x300 nid=0x61 runnable [1000..2000]
at SyncMethod.dumb(SyncMethod.java:23)
- waiting to lock <0xa00> (a SyncMethod)
at SyncMethod.run(SyncMethod.java:13)23行目でロックを獲得しているように見えますが、23行目は、“for ( ; i < 10 ; ++i)”であり、何もロック獲得に関係しているようにソースコード上は見えません。
これは、synchronizedメソッドがロックを獲得する行番号は、最初に実行される行番号になるためです。
注意
スレッドダンプ中、複数のスレッドがロックを獲得している場合ついて
次のようなプログラムを考えます。
1 class NoNotify extends Thread
2 {
3 static Object o = new Object();
4
5 public static void main(String[] arg)
6 {
7 new NoNotify().start();
8 new NoNotify().start();
9 }
10
11 public void run()
12 {
13 try {
14 synchronized (o) {
15 o.wait();
16 }
17 } catch (Exception e) {}
18 }
19
20 }このプログラムには誤りがあります。
このプログラムでは誰もnotifyするスレッドがないため、どちらのスレッドも永久に起こされることはありません。
このプログラムのスレッドダンプを採取すると次のように示される場所があります。
"Thread-1" prio=1 tid=0x800 nid=0x6 in Object.wait() [1000..2000]
at java.lang.Object.wait(Native Method)
- waiting on <0x200> (a java.lang.Object)
at java.lang.Object.wait(Object.java:429)
at NoNotify.run(NoNotify.java:15)
- locked <0x200> (a java.lang.Object)
"Thread-0" prio=1 tid=0x900 nid=0x7 in Object.wait() [3000..4000]
at java.lang.Object.wait(Native Method)
- waiting on <0x200> (a java.lang.Object)
at java.lang.Object.wait(Object.java:429)
at NoNotify.run(NoNotify.java:15)
- locked <0x200> (a java.lang.Object)このスレッドダンプから分かることは、複数のスレッドがロックを獲得しているのではなく、どのスレッドもロックを獲得していないということです。
Thread-0、Thraed-1ともに、同じオブジェクト“ID<0x200>”のオブジェクトをロックしているように見えます。
しかし“- locked”と表示されているスレッドが、現在のロックオーナであることは意味しません。（“- locked”の正確な意味するところは、そのフレームにおいてロックしたということに過ぎません。）
先頭フレームでは、“- waiting on”と表示されています。
これは、ロックが解放されたら起こされる可能性のある“- waiting to lock”とは異なり、ロックが解放されても自動的に起こされることを意味しません。
注意
Object.wait()を呼び出していないにも関わらず、「in Object.wait()」と表示される
アプリケーションから直接Object.wait()を呼び出していないにも関わらず、以下のように「in Object.wait()」と表示される場合があります。
"Thread-1" prio=10 tid=0x70257c00 nid=0x3818 in Object.wait() [0x6fe9c000]
java.lang.Thread.State: RUNNABLE
at ClassLoadContention.run(ClassLoadContention.java:10)これは、以下の例のように、複数スレッドで同じクラスをロードしようして、Java VM内部でObject.wait()と同等の処理が実行されているためです。
1 class ClassLoadContention extends Thread
2 {
3 public static void main(String[] arg)
4 {
5 new ClassLoadContention().start();
6 new ClassLoadContention().start();
7 }
8
9 public void run() {
10 TargetClass.N++;
11 }
12
13 static class TargetClass {
14 static int N;
15 static {
16 try {
17 Thread.sleep(1000);
18 } catch (Exception e) { }
19 }
20 }
21 }ポイント
JavaVM制御用のスレッド
スレッドダンプにおいて、以下の名前で出力されているスレッドは、Java VM自身の制御用スレッドです。そのため、以下の名前で出力されているスレッドの情報には、アプリケーションとしての動作状態を解析する際の直接的な情報は含まれていません。
"Attach Listener"
"C2 CompilerThread*" ("*"部分は数字です)
"Finalizer"
"RAS Control Thread"
"Reference Handler"
"Signal Dispatcher"
"VM Periodic Task Thread"
"VM Thread"
"Service Thread"
"GC task thread#* (ParallelGC)" (パラレルGC使用時に存在します) (注1)
"Concurrent Mark-Sweep GC Thread" (CMS付きパラレルGC使用時に存在します)
"Surrogate Locker Thread (Concurrent GC)" (CMS付きパラレルGC使用時に存在します)
"Gang worker#* (Parallel GC Threads)" (CMS付きパラレルGC使用時に存在します) (注1)
"Gang worker#* (Parallel CMS Threads)" (CMS付きパラレルGC使用時に存在します) (注2)
"-XX:ParallelGCThreads"オプションで指定したGC処理用スレッドの数だけ存在します。なお、名前の"*"部分は数字です。
"-XX:ConcGCThreads"オプションで指定したCMS-GC処理用スレッドの数だけ存在します。なお、名前の"*"部分は数字です。
ポイント
Javaヒープ領域に関する情報の出力
スレッドダンプの出力と合わせて、Javaヒープ領域およびメタスペースに関する情報も出力されます。
Javaヒープ領域に関する情報は、各ガーベジコレクション処理の違いにより、New世代領域、Old世代領域、メタスペースの各領域に対応する出力文字列が異なります。
なお、パーセントで示されている値は、情報出力時点でJava VMがJavaヒープ用に利用可能な状態にしている(コミットしている)メモリ量に対する比率です。利用可能な上限値に対する比率ではありません。そのため、パーセントで示されている値は参照せず、K(キロ)単位で表示されているメモリ使用量の値と、オプションで指定された値(デフォルト値を含む)とを比較する方法で各値を利用してください。
シリアルGC使用時:
「def new generation」が「New世代領域」、「tenured generation」が「Old世代領域」、「Metaspace」が「メタスペース」に関する情報です。
パラレルGC使用時:
「PSYoungGen」が「New世代領域」、「ParOldGen」が「Old世代領域」、「Metaspace」が「メタスペース」に関する情報です。
CMS付きパラレルGC使用時:
「par new generation」が「New世代領域」、「concurrent mark-sweep generation」が「Old世代領域」、「Metaspace」が「メタスペース」に関する情報です。
なお「Old世代領域」における「object space」についての情報は出力されません。
出力例：
Heap PSYoungGen total 7168K, used 5158K [0x0fd60000, 0x10470000, 0x10470000) eden space 7104K, 72% used [0x0fd60000,0x102658f0,0x10450000) from space 64K, 25% used [0x10450000,0x10454000,0x10460000) to space 64K, 0% used [0x10460000,0x10460000,0x10470000) ParOldGen total 4096K, used 162K [0x0c470000, 0x0c870000, 0x0fd60000) object space 4096K, 3% used [0x0c470000,0x0c498870,0x0c870000) Metaspace used 5118K, capacity 5162K, committed 5248K, reserved 5504K