現場から学ぶWebアプリ開発のトラブルハック 第11回

スレッドダンプの森で覚えた
死のロックへの違和感

株式会社NTTデータ　基盤システム事業本部
茂呂 範
2008/9/5

森の中で覚えた違和感

　違和感を感じたのは、次の個所だ。

ログ1　スタックトレース1（get）の強調版

at troublehack11.DBConnectionPool.get()(DBConnectionPool.java:27) - waiting to lock <0x238b5ad8> (a troublehack11.DBConnectionPool)

ログ3　スタックトレース2（wait）の強調版

at java.lang.Object.wait(Native Method) - waiting on <0x238b5ae0> (a org.apache.commons.pool.impl.GenericObjectPool)

　なんと、ほかのスレッドが待たされている排他制御個所と、このスレッドが待ち状態になっている個所で、利用されているロック用のオブジェクトが異なるのだ。

■ Javaで排他制御を必要とする際に見落としがちなもの

　Javaで排他制御を必要とするプログラムを書く際に見落としがちなものの1つに、waitメソッドを利用した際のスレッドの待機時での、ロックオブジェクトに対するロック状態がある。ここでいったん、次のサンプルプログラムを見てみよう。

プログラム1　2重ロック

public class DualLock implements Runnable {     private Object lockobj1, lockobj2;     public DualLock(Object o1, Object o2){         lockobj1 = o1; lockobj2 = o2;     }     public void run(){ lock1(); }     private void lock1(){         synchronized(lockobj1){ lock2(); }     }     private void lock2(){         synchronized(lockobj2){             try { lockobj2.wait(); }catch(InterruptedException e){}         }     }     public static void main(String[] args){         Object o1 = new Object();         Object o2 = new Object();         new Thread(new DualLock(o1, o2), "Thread1").start();         new Thread(new DualLock(o1, o2), "Thread2").start();     } }

　賢明な読者なら、このプログラムの問題点がすぐに分かったと思う。このサンプルプログラムは、2つのスレッドがlock1、lock2の順番でロックを獲得しながら、最後にlock2でwait状態へと遷移するプログラムだ。

　ロックを獲得する順番が、2つのスレッド間で同じであるため、このプログラムはデッドロックを引き起こさない。そのため直感的には、2つのスレッドはともにwait状態へと遷移してほしいところだ。

■ ロックにかかわるJavaのObject.wait()メソッドの仕様

　さて、このプログラムのどこに問題が発生するかを説明しよう。

図2　2重ロックのシーケンス図

　ロックにかかわるJavaのObject.wait()メソッドの仕様を確認すると、次のような記述がある。

「現在のスレッドはこのオブジェクトのモニターのオーナでなければなりません。スレッドはこのモニターの所有権を解放し、別のスレッドが notify メソッドまたは notifyAll メソッドを呼び出してこのオブジェクトのモニター上で待機するスレッドに通知を出すまで待機します。そのあと、スレッドはモニターの所有権を再度取得するまで待機してから実行を再開します」（引用：ObjectクラスのwaitメソッドのAPIドキュメント）

　ここでは、Object.wait()呼び出し時には、Objectのロックを解放すると記載されている。逆にいえば、waitメソッドを呼び出したObject以外の取得済みロックについては解放しないことを意味している。そのため、上記プログラム1を実行すると、次のようなスレッドダンプを得ることになる。

ログ4　2重ロックのスレッドダンプ

"Thread2" prio=6 tid=0x018e2400 nid=0x1454 waiting for monitor entry [0x03c0f000..0x03c0fd00] at troublehack11.DualLock.lock1(DualLock.java:24) - waiting to lock <0x238b5cd0> (a java.lang.Object) at troublehack11.DualLock.run(DualLock.java:20) at java.lang.Thread.run(Unknown Source) "Thread1" prio=6 tid=0x018e1c00 nid=0x15a4 in Object.wait() [0x03bbf000..0x03bbfd80] at java.lang.Object.wait(Native Method) - waiting on <0x238b5cd8> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at troublehack11.DualLock.lock2(DualLock.java:30) - locked <0x238b5cd8> (a java.lang.Object) at troublehack11.DualLock.lock1(DualLock.java:24) - locked <0x238b5cd0> (a java.lang.Object) at troublehack11.DualLock.run(DualLock.java:20) at java.lang.Thread.run(Unknown Source)

　このスレッドダンプを読むと、Thread1が「lock2(0x238b5cd8)」でwait状態へと遷移するものの、「lock1(0x238b5cd0)」のロックを解放しないため、Thread2は、lock2でロック獲得待ちのためブロックされている。

　気を付けていれば、このようなミスが発生することは少ないと思われるかもしれない。

■ そして、隠れ2重ロックも

　では、次のプログラムではどうだろうか。

プログラム2　隠れ2重ロック

private Object lock; private SomeClass logic; public void execute(){     synchronized(lock){         logic.someMethod();     } }

　一見、何も問題がないように見えるだろう。しかし、多くのAPIドキュメントには、スレッドがロックを保持してwait状態へと遷移するか否かという記述はない。そのため、SomeClassクラスのsomeMethodメソッドのソースコードを確認せずに、同じような事象が発生しないと自信を持って答えることは難しい。

　このように、2重ロックは非常に気持ちの悪い違和感を覚える実装だ。しかし、必ずしも問題が発生する訳ではない。また、システムがレスポンスを返さなくなるという問題の原因特定には至っていない。

　そこで、さらに詳細にスレッドダンプを解析することにした。

■ スタックトレースによるスレッドの分類と集計

　Javaアプリケーション内の動作状況の全貌（ぜんぼう）を把握するため、筆者はよくスタックトレースによるスレッドの分類と集計を行っている。すべてのスレッドを、その状態ごとに分類し、集計していく作業だ。今回は、Samuraiで赤く表示されているスタックトレースを1つ1つ確認することで、次のような分類と集計を得た。

表　スタックトレース集計表
スタックトレース種別	1回目のスレッドダンプ	2回目	3回目
DBCPにて待機	1	1	1
DBConnectionPool.get	34	42	55
DBConnectionPool.release	15	15	15

　これまで確認したスタックトレースとは異なるスレッドが存在した。「DBConnectionPool.release」である。この状態のスレッドは、事象発生後のスレッドダンプよりずっと同じ数だけ存在しており、次のスタックトレースを出力していた。

ログ5　スタックトレース3（release）

"TP-Processor-80" prio=6 tid=0x01b16400 nid=0xbf0 waiting for monitor entry [0x055bf000..0x055bfb80] at troublehack11.DBConnectionPool.release()(DBConnectionPool.java:42) - waiting to lock <0x238b5ad8> (a troublehack11.DBConnectionPool) ・ ・ ・ （以下略）

　このスタックトレースを確認した瞬間、さらなる違和感を体験することとなる。

1-2-3

Index
第11回　スレッドダンプの森で覚えた死のロックへの違和感
	Page1 スレッドダンプはトラブルハックに非常に有効 スレッドダンプの森に誘われ
	Page2 森の中で覚えた違和感
	Page3 翌日、ソースコードを探る 出口への道のりは、3つ 違和感の正体 仲間への信頼と高度な予測

Java Solution全記事一覧

＠ITメールマガジン　新着情報やスタッフのコラムがメールで届きます（無料）