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

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

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

翌日、ソースコードを探る

　A君にDBコネクションプールの大きさを確認すると、「15」との解答を得た。しかも、DBConnectionPool.releaseメソッドにて15スレッドがブロックされている。これは、偶然の一致とは考えづらい。

　その場で簡単な解析結果を伝えると、翌日正式にトラブル解析のために派遣された。早速、これまで解析結果を踏まえて、ソースコードを確認する。

プログラム3　get／releaseメソッド個所

synchronized public Connection get() 

                throws SQLException { ……（中略）…… }

                

                synchronized public void release(Connection con) 

                throws SQLException { ……（中略）…… }

　想像していたとおり、get／releaseメソッドにて同じロックを用いて排他制御を行っており、さらに、前述のDBCPをラッピングする形で、DBコネクションプールのクラスを独自に作りこんでいた。

■トラブル発生時の流れ

　ここで、トラブル発生時の流れを整理してみよう。

図3　トラブル発生状況の概要図

性能試験時、DBコネクションプールに空きがなくなる。
スレッド1は、コネクションを取得するため、DBConnectionPoolのコネクション取得メソッドgetを呼び出す。このとき、DBConnectionPoolのロックを取得する
コネクションプールに余裕がないため、スレッド1はDBCPのロックを用いて待機状態となる。このとき、DBConnectionPoolのロックは、言語仕様上、解放されない
コネクションを保持しているスレッド3が、DBConnectionPoolのコネクション解放メソッドreleaseを呼び出そうとする
DBConnectionPoolはロックされているため、スレッド2はreleaseメソッドにてブロックされる
releaseメソッドがロック確保待ちでブロックされるため、DBCPにコネクションが永遠に返却されず、結果的にスレッド1もDBConnectionPoolのロックを保持したまま待機状態を継続する
スレッド3のような、DBコネクションを必要とするすべてのリクエスト処理が、DBConnectionPoolのgetメソッド呼び出し時に、ロック獲得のためブロックされ、処理が停止しレスポンスが戻らなくなる

■ツールでは判断が難しいトラブル

　一般的なツールでは、この状況を瞬時に「デッドロック」と判断することは難しい。なぜなら、DBConnectionPoolのrelease処理内にてDBConnectionPoolのロック解放条件が満たされることを解析しなければならないからだ。

　これはプログラムコードを先読みして意味解釈すること、すなわちソースコードを目視で解析するか、プログラムコードを実行することにより初めて分かることを意味している。

出口への道のりは、3つ

　原因は特定されたため、暫定対処を含む3つの対策案を提示し、トラブル解析を終えた。なお、第4の案として、get／releaseメソッドで異なるロックを利用することも検討したが、内部処理の関係上、提示には至らなかった。

■対策案【1】コネクションプール数を増やす

　性能試験を実施することが最優先である場合の暫定対処案となる。根本対処にならず、DBサーバに対する負荷増につながる可能性が高い。

　さらには、コネクションプールの数はチューニングパラメータの1つでもあるため、性能試験の結果が意味を成さなくなり、かつ負荷量によっては事象が改善しない可能性もあり。そのため、試験を実施することに意味がある場合を除いては、お勧めできない。

■対策案【2】DBCPのmaxWaitを設定する

　maxWaitを設定することで、コネクション取得の永遠待ちがなくなる。その際、エラーが発生するため、エラー対処が十分にされている必要がある。

　また、必ずしも返却スレッドが優先的にロックを取得できるわけではないため、事象が改善しない可能性が高い。

■対策案【3】DBCPにアクセスする個所にて、一時的にロックを解放する

　DBConnectionPoolのget／release呼び出しからDBCPまで多重にメソッド呼び出しが行われる構造になっていた場合、メソッド呼び出しごとに細かくsynchronizedブロックを作成する必要が生じる可能性がある。

　作業量が最も多い対策案だが、根本対処とすることができ、プロジェクトによほどの事情がない限り、本対策案を選択することとなる。

■対策案【1】は、すでにやっていた

　後日A君よりお礼を兼ねたメールが来た。対策案【3】にて根本改修を行い問題を解決したとのことだった。なお、問題発生当初、対策案1をすでに実施しており、事象の発生確率を下げる効果を確認したものの問題そのものを解決することができなかった。そのため、相談という形で筆者に調査を依頼することを決めたとのことだった。

違和感の正体

　Javaの排他制御機構は非常に使いやすいものの、注意を怠ると思わぬトラブルに結び付く。今回紹介した2重ロックによるデッドロックは好例だ。

■それは、“名前”

　もっとも、今回感じていただきたかった違和感は、Javaの排他制御機構ではなく、ズバリ“名前”だ。開発者の心理として、オブジェクトプールからオブジェクトを取得する際に排他制御を行うならば、返却する場合にも同じロックで排他制御を行いたがるということだ。それが、今回でいうところの、get／releaseの組み合わせとなる。

■imagine

　オブジェクトプールや排他制御周りのトラブルにかかわらず、スレッドダンプを解析する際は、ぜひ、スタックトレース上に表れる“名前”や、その前後関係に注目してほしい。パッケージ名やクラス名、メソッド名はもちろんのこと、そこに含まれる単語にも注目する。そして、そこで何が行われているかを“想像”することが大切だ。

■それじゃ、台無し

　そんなテクニックも、次のようなスタックトレースが表れると、台無しになってしまう。辛うじて、ビジネスロジック内にて共通処理を用いて変換やバリデーションを行っているということは分かるが、具体的な処理はまったく見えてこない。

ログ6　スタックトレース4（暗号）

"T3VS258F331Q" prio=6 tid=0x018e2400 nid=0x1454 runnable [0x03c0f000..0x03c0fd00]

                at troublehack11.Utilities2.translate22(troublehack11.Utilities2.java:244)

                at troublehack11.Utilities1.validate53(troublehack11.Utilities.java:349)

                at troublehack11.C01A23BLogic.execute(troublehack11.C01A23BLogic.java:48)

                at troublehack11.C13A06BLogic.execute(troublehack11.C13A06BLogic.java:23)

                ・

                ・

                ・

                （以下略）

　さらに、スレッド名が書き換えられてしまっているため、仮にTomcat上で動作していたとしても、独自に作成されたスレッドか、Tomcatのリクエスト処理スレッドかも区別が付かない。