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

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

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

本連載は、現場でのエンジニアの経験から得られた、APサーバをベースとしたWebアプリ開発における注意点やノウハウについて解説するハック集である。現在起きているトラブルの解決や、今後の開発の参考として大いに活用していただきたい（編集部） 。

スレッドダンプはトラブルハックに非常に有効

今回の主な内容

スレッドダンプの森に誘われ 森の中で覚えた違和感 翌日、ソースコードを探る 出口への道のりは、3つ 違和感の正体 仲間への信頼と高度な予測

　Javaを用いたシステムで発生したトラブルを解析する際、スレッドダンプは非常に有効な手掛かりを指し示してくれる。

　例えば、連載第3回の「【実録ドキュメント】そのログ本当に必要ですか？」ではログ出力がボトルネックとなったトラブルを、解析ツールを用いたスレッドダンプ解析により発見している。また、連載第10回の「ThreadとHashMapに潜む無限回廊は実に面白い？」では、レースコンディション（競合状態）下においてHashMap内に無限ループが発生したトラブルを、スレッドダンプとpsコマンドの実行結果の突き合わせにより発見している。

　今回は、ちょっと変わったスレッドダンプの読み方として、スタックトレースの“字面”に着目したトラブルハックを紹介しよう。ぜひ、その“違和感”を感じとってほしい。

スレッドダンプの森に誘われ

　HashMap内に発生した無限ループ（第10回参考）の解析結果報告も兼ねて、3年ぶりに再会した同期A君と飲みに行った。このとき、A君が抱えている別案件で発生している問題の相談を受けた。なんでも、性能試験時に不可思議な出来事が起きているという。簡単に要約すると、次のとおりだ。

• 性能試験中、突如システムがレスポンスを返さなくなる
• 高い負荷で試験を行うと、発生しやすい
• ハードウェアリソースやGC（Garbage Collection）ログなどにも特に異常は見当たらない

　スレッドダンプを確認したかと尋ねると、確認してDBコネクション周りに問題があるように見えるが、DBサーバには特段異常がないため、原因が想像できないという。

　A君らしくもないと思いつつ、3カ月ほどトラブルのない生活を送り、仕事に余裕が生まれていたことも手伝い、ログを一式送ってもらえれば解析を手伝うよ、とだけ伝えてその話は終わった。

■ 真っ赤に燃えるスタックトレース

　翌日、事象再現時のログ一式を受領し、早速解析を開始した。CPU、メモリ、ディスクI/O、ネットワークI/Oともに異常はなく、GCログも至って普通の状況だった。そこで、トラブル解析フローに従い、スレッドダンプを解析することにした。

　スレッドダンプの解析には、解析ツール「Samurai」を利用したが、見事に真っ赤であった。

図1　Samuraiの真っ赤な画面

　分かりやすいトラブルでよかったと胸をなで下ろしつつも、早速、赤いスタックトレースを確認すると、以下のようになっていた。

■ 作りこまれたDBコネクションプール

ログ1　スタックトレース1（get）

"TP-Processor122" prio=6 tid=0x05779c00 nid=0x134c waiting for monitor entry [0x064df000..0x064dfa80] at troublehack11.DBConnectionPool.get()(DBConnectionPool.java:27) - waiting to lock <0x238b5ad8> (a troublehack11.DBConnectionPool) ・ ・ ・ （以下略）

　一目見て、DBコネクションプールの枯渇によるボトルネック発生を疑った。しかし、「troublehack11.DBConnectionPool」というこれまで見たことがないクラスであったため、DBコネクションプールを作り込んでいる可能性が頭をよぎる。

■ ロックを保持しているスレッドを発見しろ

　ロック競合でボトルネックが発生しているスレッドダンプを解析するときのポイントは、ロックを保持しているスレッドを発見し、そのスタックトレースを確認することだ。まずは、ロックされているオブジェクトのIDを調べるため、次の行に着目する。

ログ1　スタックトレース1のwaiting to lockの行

- waiting to lock <0x238b5ad8> (a troublehack11.DBConnectionPool)

　ここで、「<0x238b5ad8>」となっている個所が、ロックされているオブジェクトのIDとなる（※補足：ここでは便宜上「ID」と呼んでいる。この値の意味は、Java VMの実装により異なるため、普段はあまり気にしなくてよい。サン・マイクロシステムズが提供するJava VMの場合、オブジェクトが存在するメモリのアドレスを指し示しているため、GCによってオブジェクトが移動すると、この値は変化する可能性がある。よって、スレッドダンプをまたいでこの値を利用する際には、注意する必要がある）。

■ いざスレッドを発見してみると……

　次に、このロックを保持しているスレッドを検索しよう。ロックを保持しているスレッドのスタックトレースには、いましがた調べたオブジェクトのIDを伴った次のログが表れているはずだ。

ログ2　ロックを保持していることを表すスタックトレース

- locked <0x238b5ad8> (a troublehack11.DBConnectionPool)

　Samuraiでは、ログ上のオブジェクトIDの個所をクリックするだけで、ロックを保持しているスレッドのスタックトレースを表示できる。早速スタックトレースを表示すると、次のようなスレッドが得られた。

ログ3　スタックトレース2（wait）

"TP-Processor98" prio=6 tid=0x01b1cc00 nid=0xa58 in Object.wait() [0x05d5f000..0x05d5fa80] at java.lang.Object.wait(Native Method) - waiting on <0x238b5ae0> (a org.apache.commons.pool.impl.GenericObjectPool) at java.lang.Object.wait(Object.java:429) at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:748) - locked <0x238b5ae0> (a org.apache.commons.pool.impl.GenericObjectPool) at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95) at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:540) - locked <0x238b5ae0> (a java.lang.Object) at troublehack11.DBConnectionPool.get()(DBConnectionPool.java:27) - locked <0x238b5ad8>(a troublehack11.DBConnectionPool) ・ ・ ・ （以下略）

　「Apache Commons DBCP」パッケージ（以下、DBCP）のコネクション取得個所で止まっている。確かに、これはDBコネクションが不足している際に表示されるスタックトレースであり、A君の解析結果どおりの内容だ。そして、よくよくスタックトレースを呼び出し元の方へ目を移すと……。

　その違和感に思わず「えっ」と声を上げてしまった。さて、何に違和感を覚えたか、考えてみてほしい。

1-2-3

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

Java Solution全記事一覧

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