| Interstage Application Server チューニングガイド |
|
目次
索引
|
| 第7章 JDK/JREのチューニング | > 7.3 チューニング/デバッグ技法 |
スレッドダンプには、Javaプロセスの各スレッドの情報(スタックトレース形式)が含まれているため、ハングアップやデッドロックなどの動作具合を調査することができます。
スレッドダンプの出力先は、標準出力です。スレッドダンプが出力される契機および出力先を、表1に示します。
|
プログラムの種類 |
出力契機 |
出力先 |
|
J2EEアプリケーション |
一定の条件を満たした場合、コンテナの機能により自動的に採取される場合と利用者の任意のタイミングで手動による採取があります。 自動採取： 手動採取：
|
コンテナ情報ログ(info.log) |
|
J2EE以外のJavaプログラム |
利用者の任意のタイミングで手動で採取することができます。
コマンドプロンプト以外からJavaプログラムを起動した場合：
ターミナル以外からJavaプログラムを起動した場合：
|
コンソール(標準出力) |
図1の出力例をもとにして、スレッドダンプの解析方法を説明します。
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:} |
図1のサンプルでは、Thread1とThread2がお互いに排他処理を行っています。
このサンプルを実行すると、次のように処理が進められます。
この結果、Thead1とThread2がお互いに、解放されないロックを待ち続けるデッドロック状態になります。
デッドロック状態で、スレッドダンプを採取したものを、図2に示します。
"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)に移行します。
スレッドダンプからアプリケーションの状態を判断する場合、ひとつのスレッドダンプから状態を判断することは困難です。
適切な判断をするためには、複数回のスレッドダンプを総合的に見ることが必要です。
次のようなプログラムを考えます。
1class 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メソッドがロックを獲得する行番号は、最初に実行される行番号になるためです。
次のようなプログラムを考えます。
1class 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”とは異なり、ロックが解放されても自動的に起こされることを意味しません。
|
目次
索引
|
