【真夏の夜のミステリー】Tomcatを殺したのは誰だ？：現場から学ぶWebアプリ開発のトラブルハック（6）（2/3 ページ）
本連載は、現場でのエンジニアの経験から得られた、APサーバをベースとしたWebアプリ開発における注意点やノウハウについて解説するハック集である。現在起きているトラブルの解決や、今後の開発の参考として大いに活用していただきたい。（編集部）
【第4章】ログはすべてを物語る
フロー上では「3：メソッドプロファイリング」か「4：プールオブジェクト分析」に進むべきところだ。しかし、現在のシステムでは、どちらも設定を行っていないため、これらの情報を取得するには、Tomcatの再起動が必要となる。そのうえ、スレッドダンプと同様、問題が発生したときに情報を取得しないと、原因にはたどり着けないだろう。
■担当者「気になるところがある」
次の一手を考えあぐねていたところ、ログの整理をしていた担当者からTomcatのログファイルに気になるところがあるとの連絡を受けた。
早速見てみると、以下のようなメッセージが、問題が発生した時間帯よりちょっと前に、出力されていた。
2007/xx/xx xx:28:50 org.apache.tomcat.util.threads.ThreadPool logFull 致命的: すべてのスレッド (200) が現在稼働中で待機しています。maxThreads (200) を増やすか、そのサーブレットのステータスをチェックしてください
これは、Tomcatの持つスレッドプールが最大スレッド数に達してしまったという内容のメッセージだ。Tomcatは、スレッドの生成／破棄のオーバヘッドを削減するため、スレッドプーリングの機能を持っている。スレッドの数が多過ぎるとサーバ上のリソースを消費し過ぎてしまうため、プールには上限値として最大スレッド数を設定できる。
■Tomcat解剖
それでは、最大スレッド数に達した場合にはどうなってしまうのか。それを理解するためには、Tomcat内部の動作に関する知識が必要となる。図3はTomcat内部の動作を示している。
新規に接続したコネクションは、まずキューに積まれ、acceptスレッドによりキューから取り出される。acceptスレッドはプール内の空いているworkerスレッドにコネクションを渡し、workerスレッドがクライアントとのやりとりを処理する。
クライアントとのやりとりが終わりコネクションが切断されるとworkerスレッドはプールに返る。スレッドプールが最大スレッド数に達してしまうと、新規のコネクションはworkerスレッドがプールに返るのを待つことになる。
■１つの可能性が見つかる
Tomcatに直接接続して切断するようなクライアントの場合、ほかのコネクションが切れるのを待てばいいので無応答になることはない。しかし、ApacheとTomcatの間のコネクションはmod_jkによって維持される。いったん、最大スレッド数に達してしまうと、以降にキューに入った新規コネクションに対してスレッドは割り当てられず、無応答になってしまうのだ！
このメッセージは、問題が発生した時間帯よりもちょっと前に出力され、問題発生時には出力されていなかった。
実はこのメッセージは、Tomcat起動後、最初に最大値を超えたときにしか出力されない。そのため、問題発生時にも最大値を超え続けていたかどうかは分からず、これが原因であると断定することはできない。しかし、原因である可能性が非常に大きいと思われたため、ミドルウェアの設定ファイルを確認することにした。
【第5章】トラブル再発！ → 裏を取る
と、ここで問題が再発したとプロジェクト側から連絡があった。
スレッド不足に陥っているならば、tcp（プロトコル）のコネクション状態に異常が見られるはずだ。すぐさまnetstatコマンドを使用して、Tomcatが動作しているサーバ上でport8009のコネクションを確認すると、リスト2の状態になっていた。
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の設定ファイルを確認してみた。
<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を確認した。
<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倍になっていたのだ。
つまり、今回のシステムではTomcatのmaxThreadsに300以上の値が設定されていなければならないことになる。
問題発生時に内部セグメントからは問題なく接続できていた理由もこれで説明が付く。Tomcatは直接リクエストを受け付けるためのport（8080）とApache-mod_jk経由のリクエストを受け付けるport（8009）それぞれにスレッドプールを持っている。そのため、一方のスレッドプールが最大値に達してしまっても、もう一方には影響を与えなかったのだ……
Copyright © ITmedia, Inc. All Rights Reserved.