| Interstage Application Server トラブルシューティング集 |
|
目次
索引
|
| 第19章 Java実行環境運用時の異常 |
スレッドダンプはJavaプロセスの各スレッドのスタックトレースです。このスタックトレースを解析することで、そのプロセスの動作や問題点の調査を確認することが可能です。
スレッドダンプはアプリケーションがタイムアウトまたは無応答になった場合に自動採取されます。
アプリケーション
出力方法
出力場所
Servlet/JSP/EJBアプリケーション
アプリケーションがタイムアウトまたは無応答になった場合に自動採取。
コンテナ情報ログ(info.log)
その他のJavaアプリケーション
コマンドプロンプトから、Javaプログラムを起動した場合、[Ctrl]キーを押しながら [Break] キーを押し採取。
また、“スレッドダンプツール”でも採取できます。
kill -Quit [プロセスID]でJavaVMに対してQUITシグナルを送ったとき採取。
(プロセスIDは管理コンソールで参照できます。)標準出力
スレッドダンプはJavaプロセスの各スレッドの情報を参照することができるため、ハング時、特にデッドロックが発生している場合に、原因調査に有効な情報を与えます。
以下にデッドロックのサンプルプログラムと、スレッドダンプの出力例を示します。
--------------------------------------------------------------------------------
public class Deadlock implements Runnable {
volatile boolean finished = false;
public void run() {
try {
synchronized (this) {
while (!finished) {
System.out.print(".");
Thread.sleep(500);
}
}
}
catch (InterruptedException ex) {
ex.printStackTrace(System.out);
Thread.currentThread().interrupt();
}
}
public static void main(String args[]) {
Object obj = new Object();
Deadlock test = new Deadlock();
Thread th = new Thread(test, "Child");
try {
th.start();
Thread.sleep(5000);
synchronized (test) {
test.finished = true;
}
}
catch (Exception ex) {
ex.printStackTrace(System.out);
}
}
}
--------------------------------------------------------------------------------
本サンプルプログラムは、run()メソッドで DeadLockクラスのインスタンスに対してsynchronized句により、ロックを取得しています。run()メソッドは、finishedフラグがfalseの間ループを繰り返します。
一方、main()メソッドは、run()メソッド呼び出し後に、DeadLockクラスのインスタンスに対してロックを獲得できたならば、finishedフラグをtrueに設定します。この例の場合run()メソッドが、DeadLockクラスのインスタンスに対してロックを獲得していますので、main()メソッドはロックを獲得することができずに、ハングアップします。
スレッドダンプの出力例は次のとおりです。
--------------------------------------------------------------------------------
"Thread-0" prio=10 tid=0x8ae1d0 nid=0x658 waiting on monitor [0..0x8eefd38]
"Child" prio=5 tid=0x89d9038 nid=0x630 waiting on monitor [0x8d8f000..0x8d8fdbc]
at java.lang.Thread.sleep(Native Method)
at Deadlock.run(Deadlock.java:9)
- locked <29700b8> (a Deadlock)
at java.lang.Thread.run(Thread.java:479)
"Signal Dispatcher" daemon prio=10 tid=0x80f5a0 nid=0x674 waiting on monitor [0..0]
"Finalizer" daemon prio=9 tid=0x8990d10 nid=0x2b0 waiting on monitor [0x8c4f000..0x8c4fdbc]
at java.lang.Object.wait(Native Method)
- waiting on <2930328> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:103)
- locked <2930328> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:157)
"Reference Handler" daemon prio=10 tid=0x8990078 nid=0x444 waiting on monitor [0x8c0f000..0x8c0fdbc]
at java.lang.Object.wait(Native Method)
- waiting on <2930238> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:415)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:105)
- locked <2930238> (a java.lang.ref.Reference$Lock)
"main" prio=5 tid=0x282900 nid=0x6a4 waiting for monitor entry [0x6f000..0x6fc34]
at Deadlock.main(Deadlock.java:26)
- waiting to lock <29700b8> (a Deadlock)
"VM Thread" prio=5 tid=0x28d9c8 nid=0x6cc runnable
"VM Periodic Task Thread" prio=10 tid=0x803ae8 nid=0x628 waiting on monitor
"Suspend Checker Thread" prio=10 tid=0x80ec58 nid=0x6dc runnable
--------------------------------------------------------------------------------
各スレッドの情報は、スタックトレースの見方と同じで、下から参照します。
本スレッドダンプの場合、デッドロックの状況ですのでlock情報を確認します。
この事例では、「→」で示したスレッド間でデッドロックしていることがわかります。
ループを調べるためには、複数回スレッドダンプを採取し、同じスレッドが動作していないか確認します。
応答がない場合に要求(Request)待ちのメソッドが出ていないか確認し、そこから原因を調査する方法もあります。
また、スレッドダンプについては、“スレッドダンプが出力された場合の対処”も参照してください。
オブジェクトをロックしているスレッドがスレッドダンプ上に出ない
通常スレッドダンプ上のあるスレッドで次のように表示される場合があります。
- 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)に移行します。
スレッドダンプからアプリケーションの状態を判断する場合、ひとつのスレッドダンプから状態を判断することは困難です。
適切な判断をするためには、複数回のスレッドダンプを総合的に見ることが必要です。
次のようなプログラムを考えます。-------------------------------------------------------------------------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”とは異なり、ロックが解放されても自動的に起こされることを意味しません。
|
目次
索引
|