数百キロのコードでブルー - ドクターTomcat緊急救命：現場から学ぶWebアプリ開発のトラブルハック（14）（1/2 ページ）

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

» 2010年05月25日 00時00分公開

[岡本隆史，＠IT]

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

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

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

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

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

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

　まず問題があるサーバが起動しているホストにログインし、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）ところで待ち状態になっていることが判明した。どうやら、コネクションを取得する際に、コネクションの解放待ちで止まっているようだ。

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

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

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

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