「現場から学ぶWebアプリ開発のトラブルハック」連載一覧へ
現場から学ぶWebアプリ開発のトラブルハック 第14回

数百キロのコードでブルー
- ドクターTomcat緊急救命


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

人は真実を知りたがる…… そして、不幸が始まる

今回の主な内容
人は真実を知りたがる…… そして、不幸が始まる
身体検査 - ダンプはシステムが生きた証だ
患部特定 - なぜバグのすべてを引き受けようとするんだ
 腫瘍摘出 - バグだと思って…… 切ります
予防処置 - 愛と勇気だけではシステムはよみがえらない
この国には、もっと救えるシステムがある
【おまけ】ほかのアプリケーションサーバでの調べ方

　ある晴れた日、温かい太陽の光を体に浴びながら、めずらしく爽快な気分で会社に出社した。しかし、その爽快な気分も長くは続かなかった。出社するなり、上司から次のようにいわれた。

「茨城で開発しているシステムが、リリース直前にナゾのフリーズに悩まされているようだ。支援依頼があったのだが、ちょっといって原因を調べてやってくれないか」

　今回の現場は、都心から少し離れている。私は特急の乗車券を確保し、早速現地に向かった。私の気分を汲み取ったかのように、太陽は雲にかくれ、冷たい雨が降り出した。

身体検査 - ダンプはシステムが生きた証だ

　現場に着くと、システムが最初は普通に動作しているが、そのうちレスポンスを返さなくなるということを聞かされた。取りあえず、レスポンスを返さなくなった状態で取りあえずスレッドダンプを取り停止している場所の特定を試みる。

　まず問題があるサーバが起動しているホストにログインし、JDKのあるディレクトリに移動しJavaプロセスを確認する。Javaプロセスの確認にはpsコマンドを利用してもいいが、jpsコマンドを利用すると簡単にJavaプロセスだけ確認できるので、これを使おう。


# cd /usr/java/jdk1.6.0_18/bin
# ./jps  -lv
2764 org.apache.catalina.startup.Bootstrap -Djava.util.logging.config.file=/usr/local/tomcat6/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/usr/local/tomcat6/endorsed -Dcatalina.base=/usr/local/tomcat6 -Dcatalina.home=/usr/local/tomcat6 -Djava.io.tmpdir=/usr/local/tomcat6/temp
24742 sun.tools.jps.Jps -Dapplication.home=/usr/java/jdk1.6.0_18 -Xms8m

　「2764」がorg.apache.catalina.startup.Bootstrapクラスを実行している。これはTomcatの起動クラスなので、これがこのシステムを動かしているプロセスだ。

　早速、このプロセスのスレッドダンプを取得しよう。「kill -3(kill -QUIT)」を利用してもいいが、これだと、Javaプロセスを起動したコンソールに出力されてしまい分かりにくいし、そもそもどのファイルにJVMのコンソール出力が出されているか調べる必要がある。jstackコマンドを利用すれば、現在起動しているコンソールから簡単にスレッドダンプを出力できる。


# ./jstack 2764
 
2010-03-05 09:40:31
Full thread dump Java HotSpot(TM) Client VM (16.0-b13 mixed mode):
 
"http-8080-13" daemon prio=6 tid=0x173b7000 nid=0x1c74 in Object.wait() [0x17e9f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x02b610f0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Latch)
	at java.lang.Object.wait(Object.java:485)
	at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1104)
	- locked <0x02b610f0> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Latch)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
	at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
	at com.foo.servlet.LoginServlet.service(TestServlet.java:28)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
 
…【略】…
 
"http-8080-12" daemon prio=6 tid=0x173b3800 nid=0x1c68 in Object.wait() [0x17e4f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x02b47970> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Latch)
	at java.lang.Object.wait(Object.java:485)
	at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1104)
	- locked <0x02b47970> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool$Latch)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
	at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
	at com.foo.servlet.LoginServlet.service(TestServlet.java:28)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
 
…【以下略】…

患部特定 - なぜバグのすべてを引き受けようとするんだ

　スレッドダンプを見ると、WAITING状態のデータベースのコネクションが多数あり、さらにほとんどのWAITING状態のスレッドは、GenericObjectPool.borrowObjectメソッド、つまり、コネクションをプールから借りる（borrow）ところで待ち状態になっていることが判明した。どうやら、コネクションを取得する際に、コネクションの解放待ちで止まっているようだ。

「データベースコネクションの解放漏れですね。おそらくクローズしていないコネクションが何処かにあるはずです。コードレビューをしてコネクションのクローズ漏れがある個所を探してください。では、今日は予定があるので、これで失礼します」

　と、取りあえず原因究明だけして、その場を去ろうとした。コネクションのクローズ漏れの問題はやっかいた。長居は無用である。すると、

「ちょっと、待ってください。帰るんですか。手伝ってくださいよ」

　原因調査は依頼されたが、「不具合の修正は自分の担当範囲ではないのでは」と一応抵抗してみたが、抵抗空しく残念ながら私は、この現場に留まることとなった。

腫瘍摘出 - バグだと思って…… 切ります

　さて、コネクションのクローズ漏れが発生している個所を探すことになった。私は、順を追って解析することにした。

■ ステップ【1】スレッドが停止している付近の調査

　まずは、スレッドが停止しているところからソースコードを調査した。しかしながら、スレッドが停止している場所でコネクションの解放漏れを起こしている個所はなさそうだった。

　このような障害では、スレッドが停止した場所に問題があるわけではなく、スレッドが停止する前に徐々にコネクションを食いつぶしていった場所に問題がある。そのため、残念ながらスレッドダンプからでは解析できないことも多い。

■ ステップ【2】FindBugsの利用

　FindBugsは、その名の通りバグを検出するツールである。ソースコードにFindBugsを使うと、コーディング上の簡単なバグを検出してくれる。FindBugsで検出できるバグの中にコネクションの解放漏れの可能性があるコードの検出があり、試してみる価値はあると考えた。

http://findbugs.sourceforge.net/

FindBugs − Find Bugs in Java Programs via kwout

　FindBugsのプラグインをインストールしていれば、プロジェクトのメニューから「バグを検索」でFindBugsを実行できる（図1）。

図1　samuraiの真っ赤な画面
図1　FindBugsの実行

　ソースコードにFindBugsを使ってみると、結果、クローズ漏れが発生している個所を数カ所特定できた（図2）。

図2　検出されたコネクションのクローズ漏れ
図2　検出されたコネクションのクローズ漏れ

　FindBugsの詳細は、下記記事も参照されたい。

　早速ソースコードを修正して試験したが、アプリケーションが動作する時間は以前よりは長くなったものの、長時間動作させると同様の現象でアプリケーションが固まってしまう。スレッドダンプを調べてもコネクションの解放待ちで止まっているのには変わりなかった。

　すべてのソースコードをレビューしてコネクションの解放漏れを起こしている個所を摘出するしかないのか。しかし、数百キロステップもあるコードから果たして問題の個所を特定できるだろか。そもそも、いまいちな他人が書いたコードなんて、大量に読みたくはない。気分がブルーになっていく……。

　次ページでは、ステップ【3】として、コネクションプールのリーク検出機能を試す。そして、予防処置へ。

1-2

Index
第14回　数百キロのコードでブルー - ドクターTomcat緊急救命
Page1
人は真実を知りたがる…… そして、不幸が始まる
身体検査 - ダンプはシステムが生きた証だ
患部特定 - なぜバグのすべてを引き受けようとするんだ
腫瘍摘出 - バグだと思って…… 切ります
  Page2
予防処置 - 愛と勇気だけではシステムはよみがえらない
この国には、もっと救えるシステムがある
【おまけ】ほかのアプリケーションサーバでの調べ方

現場から学ぶWebアプリ開発のトラブルハック バックナンバー 連載インデックスへ»


Java Solution全記事一覧


TechTargetジャパン

Java Solution フォーラム 新着記事

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

RSSフィード

＠IT 新着記事

キャリアアップ

- PR -
＠IT Sepcial
→ ＠IT Special ヘ

イベントカレンダー

PickUpイベント

- PR -
もっと見る
- PR -

お勧め求人情報

ホワイトペーパー（TechTargetジャパン）

＠IT Sepcial
→ ＠IT Special ヘ
ソリューションFLASH