【トラブル大捜査線】失われたコネクションを追え！：現場から学ぶWebアプリ開発のトラブルハック（7）（2/3 ページ）

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

【第3話】Tomcatの持つコネクションプール「DBCP」

■netstatコマンドによる確認

　あるプログラムがソケットを使用してほかのプログラムと通信している場合、netstatコマンドを使用してソケットの状態を確認するといろいろなことが分かる。

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

　早速、netstatでDBコネクションの状態を見てみると、確立済み（ESTABLISHED）状態のコネクションが、DBCPに設定している最大コネクション数と同じ数だけ存在した。Tomcatの設定を確認してみると、DBCPの最大コネクション数はTomcatの最大スレッド数と同じ値に設定してあった。つまり、スレッドが同時に複数のコネクションを使用しない限りコネクションが不足することはない。

■リーダー「同時に1つのコネクションしか使わないはず」

　アプリケーション開発のリーダーに確認したところ、「アプリケーションは同時に1つのコネクションしか使わないようコーディングされているはず」とのことだった。

　足りるはずのコネクションが不足した。ここから想定される原因は、おそらくコネクションのクローズ漏れだろう。

■“コネクションのクローズ漏れ”とは？ どんな影響がある？

　コネクションのクローズ漏れがTomcatの無応答につながる理由について、もう少し詳しく見ておこう。

　DBCPのようにコネクションプールを実装するライブラリは、実際のConnectionオブジェクトをラップしたクラスを用意する。そのラップしたクラスのオブジェクトのclose()メソッドを呼ぶと、コネクションは実際にはクローズされず、プールに返却される。

　そして、クローズ漏れが発生すると、プールに戻らないコネクションが生まれてしまう。

図3　コネクションプールの仕組みとクローズ漏れ

　プールのコネクション数が上限に達し、不足した場合、後続のコネクション取得処理はプールから取り出すところで待ちとなる。そのため、無応答になってしまうのだ。

　クローズ漏れを起こしたコネクションはどうなるのか？

　実コネクションに関しては、GCされたタイミングでfinalizeメソッドにより物理的なコネクションをクローズするように実装されている。しかし、DBCPのラッパーオブジェクトはfinalizeを実装しておらず、GCによってプールに戻ってくることもない。

【第4話】失われたコネクションを追え！

　さて、スレッドダンプとnetstatコマンドによりコネクションのクローズ漏れが原因であると目安を付けたものの、解決するにはもうひと手間が必要だ。なぜなら、スレッドダンプは「コネクションを獲得しようとしている」スレッドを検出することはできるが、「コネクションをクローズし忘れた」処理についての情報は何も教えてくれないからだ。

　アプリケーションのコードを修正するためには、すべてのソースコードを見直してクローズ漏れがないかどうかチェックしなくてはならない。アプリケーション開発のリーダーに相談したところ、「試験工程のスケジュールがすでに遅れており、すべてのソースコードチェックを行うような人手は掛けられない」とのことだった。

■DBCPのremoveAbandoned機能を試す

　そこで、DBCPの持つremoveAbandoned機能を試してみることにした。DBCPには、クローズ漏れ（見捨てられた：abandoned）となったコネクションを回収する仕組みが存在する。

図4　removeAbandoned機能

　removeAbandonedを有効にすると、コネクションをプールから取り出す際に、“trace”リストにコネクションへの参照が格納される。コネクションには、そのときの呼び出しのstackTrace情報が保存される。

　そして、プールから取り出されたコネクションの数がプールの最大値（maxActive）に近づくと、コネクションの取得を要求したスレッドは、“trace”リストを基に、取り出しから一定時間たったコネクションを追跡、closeを呼ぶことでプールにコネクションを返却する。

　removeAbandonedを有効にするには、DataSourceの設定で、リスト4のようにパラメータを追加する。

リスト4　DataSource設定

<Resource name="jdbc/postgres" auth="Container"     type="javax.sql.DataSource"     driverClassName="org.postgresql.Driver"     url="jdbc:postgresql://192.168.xxx.xxx:5432/webdb"     username="postgres" password="xxxxxx"     maxActive="200" maxIdle="100" maxWait="-1"     removeAbandoned=”true” removeAbandonedTimeout=”60”     logAbandoned=”true” />

　パラメータの内容の詳細については、後述する。

■ついに、コネクションのクローズ漏れを検出！

　removeAbandonedパラメータを設定し、再度負荷試験を行うと、Tomcatのログにリスト5のようなstackTraceが出力された。

リスト5　removeAbandonedによるstackTrace （拡大したものはこちら）

DBCP object created 2007-xx-xx 14:53:32 by the following code was never closed: java.lang.Exception     at org.apache.tomcat.dbcp.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java:157)     at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:76)     at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)     at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:540)     at jp.co.intellilink.manage.LogoutBean.doExec(LogoutBean.java:142)     at org.apache.jsp.manage.logout_jsp._jspService(logout_jsp.java:21)     at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)     at javax.servlet.http.HttpServlet.service(HttpServlet.java:803) ……省略……

　stackTraceはどれも同じメソッド、LogoutBean.doExecメソッドを示している。

　どうやら、このメソッドの後続の処理でクローズ漏れがありそうだ。