スレッドダンプの森で覚えた死のロックへの違和感：現場から学ぶWebアプリ開発のトラブルハック（11）（2/3 ページ）

» 2008年09月05日 00時00分公開

[茂呂範，株式会社NTTデータ]

森の中で覚えた違和感

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

ログ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 次のページへ

SpecialPR