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

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

[茂呂範,株式会社NTTデータ]
前のページへ 1|2|3       

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

 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 トラブル発生状況の概要図 図3 トラブル発生状況の概要図
  1. 性能試験時、DBコネクションプールに空きがなくなる。
  2. スレッド1は、コネクションを取得するため、DBConnectionPoolのコネクション取得メソッドgetを呼び出す。このとき、DBConnectionPoolのロックを取得する
  3. コネクションプールに余裕がないため、スレッド1はDBCPのロックを用いて待機状態となる。このとき、DBConnectionPoolのロックは、言語仕様上、解放されない
  4. コネクションを保持しているスレッド3が、DBConnectionPoolのコネクション解放メソッドreleaseを呼び出そうとする
  5. DBConnectionPoolはロックされているため、スレッド2はreleaseメソッドにてブロックされる
  6. releaseメソッドがロック確保待ちでブロックされるため、DBCPにコネクションが永遠に返却されず、結果的にスレッド1もDBConnectionPoolのロックを保持したまま待機状態を継続する
  7. スレッド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のリクエスト処理スレッドかも区別が付かない。

仲間への信頼と高度な予測

 今回は、スレッドダンプに表れる名前から処理の内容を予想し、トラブルの解析へつなげるテクニックを紹介した。

 ただ残念なことに、このテクニックは、開発者が信頼できること、正確には開発者の行動(名付け)に対する自分の予測の精度が高い場合に初めて成り立つテクニックとなる。そのため、本テクニックを活用する際は、自分の予測が外れていた場合を常に念頭に置いて、トラブルハックを行っていただきたい。

 また、ソースコードの保守性、特に読みやすさのため、名前が重要であることが叫ばれて久しいが、トラブルハックの観点でも同じことがいえるだろう。

プロフィール

茂呂 範(もろ すすむ)

株式会社NTTデータ 基盤システム事業本部所属。入社時よりOSSを用いたWebシステムの開発支援にかかわる。最近では、トラブルシューティングとその際のノウハウの収集・展開に日々従事している。



前のページへ 1|2|3       

Copyright © ITmedia, Inc. All Rights Reserved.

RSSについて

アイティメディアIDについて

メールマガジン登録

@ITのメールマガジンは、 もちろん、すべて無料です。ぜひメールマガジンをご購読ください。