【真夏の夜のミステリー】Tomcatを殺したのは誰だ？：現場から学ぶWebアプリ開発のトラブルハック（6）（2/3 ページ）

[金子崇之，NTTデータ先端技術]

【第4章】ログはすべてを物語る

　フロー上では「3：メソッドプロファイリング」か「4：プールオブジェクト分析」に進むべきところだ。しかし、現在のシステムでは、どちらも設定を行っていないため、これらの情報を取得するには、Tomcatの再起動が必要となる。そのうえ、スレッドダンプと同様、問題が発生したときに情報を取得しないと、原因にはたどり着けないだろう。

■担当者「気になるところがある」

　次の一手を考えあぐねていたところ、ログの整理をしていた担当者からTomcatのログファイルに気になるところがあるとの連絡を受けた。

　早速見てみると、以下のようなメッセージが、問題が発生した時間帯よりちょっと前に、出力されていた。

リスト1　Tomcatのエラーメッセージ

2007/xx/xx xx:28:50 org.apache.tomcat.util.threads.ThreadPool logFull
致命的: すべてのスレッド (200) が現在稼働中で待機しています。maxThreads (200) を増やすか、そのサーブレットのステータスをチェックしてください

　これは、Tomcatの持つスレッドプールが最大スレッド数に達してしまったという内容のメッセージだ。Tomcatは、スレッドの生成／破棄のオーバヘッドを削減するため、スレッドプーリングの機能を持っている。スレッドの数が多過ぎるとサーバ上のリソースを消費し過ぎてしまうため、プールには上限値として最大スレッド数を設定できる。

■Tomcat解剖

　それでは、最大スレッド数に達した場合にはどうなってしまうのか。それを理解するためには、Tomcat内部の動作に関する知識が必要となる。図3はTomcat内部の動作を示している。

図3　コネクションとスレッド

　新規に接続したコネクションは、まずキューに積まれ、acceptスレッドによりキューから取り出される。acceptスレッドはプール内の空いているworkerスレッドにコネクションを渡し、workerスレッドがクライアントとのやりとりを処理する。

　クライアントとのやりとりが終わりコネクションが切断されるとworkerスレッドはプールに返る。スレッドプールが最大スレッド数に達してしまうと、新規のコネクションはworkerスレッドがプールに返るのを待つことになる。

■１つの可能性が見つかる

　Tomcatに直接接続して切断するようなクライアントの場合、ほかのコネクションが切れるのを待てばいいので無応答になることはない。しかし、ApacheとTomcatの間のコネクションはmod_jkによって維持される。いったん、最大スレッド数に達してしまうと、以降にキューに入った新規コネクションに対してスレッドは割り当てられず、無応答になってしまうのだ！

　このメッセージは、問題が発生した時間帯よりもちょっと前に出力され、問題発生時には出力されていなかった。

　実はこのメッセージは、Tomcat起動後、最初に最大値を超えたときにしか出力されない。そのため、問題発生時にも最大値を超え続けていたかどうかは分からず、これが原因であると断定することはできない。しかし、原因である可能性が非常に大きいと思われたため、ミドルウェアの設定ファイルを確認することにした。

【第5章】トラブル再発！ → 裏を取る

　と、ここで問題が再発したとプロジェクト側から連絡があった。

　スレッド不足に陥っているならば、tcp（プロトコル）のコネクション状態に異常が見られるはずだ。すぐさまnetstatコマンドを使用して、Tomcatが動作しているサーバ上でport8009のコネクションを確認すると、リスト2の状態になっていた。

リスト2　port8009のコネクションの状態

Proto Recv-Q Send-Q Local Address         Foreign Address        State
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.172:38910  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.171:28897  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.172:38309  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.171:23301  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.172:38898  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.171:28396  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.172:38911  SYN_RECV
tcp        0      0 xxx.xxx.160.153:8009  xxx.xxx.161.172:56606  ESTABLISHED
tcp      159      0 xxx.xxx.160.153:8009  xxx.xxx.161.172:36894  ESTABLISHED

　SYN_RECVとは、コネクションの接続要求であるSYNパケットを受け取り、応答となるACKパケットを返していない状態だ。Tomcatが処理できる以上に新規コネクションが要求されており、接続要求がキューに積まれていることになる。

　どうやら原因は、Tomcatのスレッド数不足で間違いないようだ。

編集部注：tcp、netstatコマンド、SYN、ACKについて詳しく知りたい読者は、＠IT Master of IP Networkの「ホストのネット接続は正しく行われているか？〜netstatによるネットワーク設定の確認〜」をご参照ください。

■Apacheの設定ファイルを確認

　そこで、Apacheの設定ファイルを確認してみた。

リスト3　Apacheの設定ファイル

<IfModule worker.c>
StartServers       10
MaxClients         150
MinSpareThreads    150
MaxSpareThreads    150
ThreadsPerChild    15
</IfModule>

　Apache（worker MPM）の最大スレッド数は、MaxClientsで設定される。このシステムでは、150に設定されていた。

■Tomcatのserver.xmlも確認

　次に、Tomcatのserver.xmlを確認した。

リスト4　Tomcatのserver.xml

<Connector port="8009" 
maxThreads="200" minSpareThreads="25" maxSpareThreads="200"
backlog="100" connectionTimeout="20000"
enableLookups="false" redirectPort="8443" protocol="AJP/1.3" />

　ConnectorのmaxThreads値は、エラーメッセージどおりに200に設定されていた。MaxClients値よりも大きい値が設定されているため、一見問題がないように見える。

　しかし、今回のシステムではWebサーバは2台あり、それぞれ2台のAPサーバに負荷分散を行っていた。APサーバから見た接続元となるWebサーバは2台になるため、コネクションの数も2倍になっていたのだ。

図4　コネクションの接続状態の図

　つまり、今回のシステムではTomcatのmaxThreadsに300以上の値が設定されていなければならないことになる。

　問題発生時に内部セグメントからは問題なく接続できていた理由もこれで説明が付く。Tomcatは直接リクエストを受け付けるためのport（8080）とApache-mod_jk経由のリクエストを受け付けるport（8009）それぞれにスレッドプールを持っている。そのため、一方のスレッドプールが最大値に達してしまっても、もう一方には影響を与えなかったのだ……