TomcatとOracle間のコネクションプーリングに関するトラブルシューティング
Tomcatでコネクションプーリングを使用していて、Tomcat <-> Oracle間の接続がFINやRSTパケットによる通知なしに切られた場合、プールしている接続が実際には死んでいる状態が発生する。例えば、以下のような場合に発生する。
- APサーバー <-> DBサーバー間のFirewallによるセッション切断
- DBサーバーのリブート(Windows Server 2008の場合。他は未確認)
なお、Windows Server 2008で試した限りではOracleサービスの再起動やshutdown、startupの場合は発生しなかった。おそらくFINまたはRSTパケットが飛んでいると思われる。
一度、この状態に陥ると、その後ネットワークやDBサーバーが復旧しても死んだ接続がプールに残り続け、その接続を使用したTomcatのスレッドはSQLを実行する処理でOracleからの応答をずっと待ちつづけてしまう。
特にDBCPの設定でtestOnBorrow、validationQueryによりプールからの接続取得時にSQL実行による接続の検証を行うようにしていると、検証SQL実行時に応答待ちになり、しかもvalidationQueryの実行はプールからの接続の取得処理内で行われるため(接続数の管理のために)処理が同期化されているため、他のスレッドがプールから接続を取得するのをブロックする状況になり、やがてTomcatのmaxThreadsやHTTPサーバーの接続上限に達し、応答停止状態になる。
ブロックしているスレッドのスタックトレースはこんな感じになる。(S2JDBCを使用)
"TP-Processor48" daemon prio=10 tid=0x00002aaafc638000 nid=0x6d4a runnable [0x0000000046684000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at oracle.net.ns.Packet.receive(Packet.java:240) at oracle.net.ns.DataPacket.receive(DataPacket.java:92) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:172) at oracle.net.ns.NetInputStream.read(NetInputStream.java:117) at oracle.net.ns.NetInputStream.read(NetInputStream.java:92) at oracle.net.ns.NetInputStream.read(NetInputStream.java:77) at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1034) at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1010) at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:588) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:183) at oracle.jdbc.driver.T4CStatement.executeForDescribe(T4CStatement.java:780) at oracle.jdbc.driver.T4CStatement.executeMaybeDescribe(T4CStatement.java:855) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1178) at oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:1377) - locked <0x00002aaae90bd2e8> (a oracle.jdbc.driver.T4CConnection) at oracle.jdbc.driver.OracleStatementWrapper.executeQuery(OracleStatementWrapper.java:387) at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208) at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208) at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:658) at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:635) at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1165) at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044) at org.seasar.extension.dbcp.impl.DataSourceXADataSource.getXAConnection(DataSourceXADataSource.java:80) at org.seasar.extension.dbcp.impl.ConnectionPoolImpl.createConnection(ConnectionPoolImpl.java:430) at org.seasar.extension.dbcp.impl.ConnectionPoolImpl.checkOut(ConnectionPoolImpl.java:350) - locked <0x00002aaaee21a4e8> (a org.seasar.extension.dbcp.impl.ConnectionPoolImpl)
netstatでいうと、APサーバー側でESTABLISHEDのTCPセッションが、DBサーバー側には存在しない状態になる。
この問題を解決すべく色々調査したのでまとめておく。
なお、調査で色々試した環境はTomcat 6.0.29@Red Hat Enterprise Linux 5、Oracle 11gR1@Windows Server 2008R2。
実現したいこと
DBサーバーやネットワーク障害発生時に、復旧次第、自動的にTomcat <-> Oracle間の接続が復旧するようにしたい。
そのために、validationQueryのタイムアウト時間は短く設定し、接続が切断されていることをOSのTCP/IP KeepAliveタイムアウト時間まで待たずにもっとすぐに検知してタイムアウトさせたい。
タイムアウトさせることでDBCPでその接続を破棄して再接続させる(testOnBorrowの機能)ことで、DB側やネットワークが復旧次第Tomcat <-> Oracle間の接続も復旧させることが可能。
一方で、アプリケーションのSQLが処理中にタイムアウトさせられてしまうことは避けたい。
調査したこと
1.Statement#setQueryTimeout()
JDBCではSQLのタイムアウトにはこれを使うのがおそらく標準だが、Oracle JDBC Driverでは今回のような場面ではこれは効かない。これはOracle JDBC Driverのクエリタイムアウトの仕組みが、単純にタイムアウト時間を超えたらエラーを返すものではなく、タイムアウト時間を超えたらOracleサーバーにクエリキャンセル要求を行い、その結果をもってタイムアウトエラーをクライアントに返すものだから。*1今回のように接続が死んでいてキャンセル要求の応答も返ってこない場合は、タイムアウトせず待ち続けてしまう。
なお、調査の過程で見つけたのだが、DBCPには現時点ではDBCP – BasicDataSource Configurationには記載されていないvalidationQueryTimeoutというvalidationQueryのタイムアウト時間を設定する隠し？パラメータがあるのだが、これも実装はStatement#setQueryTimeout()を実行しているだけなので今回は使えない。
もちろん、Oracle JDBC Driverでも、今回のように接続が切れてしまっている場面でなければStatement#setQueryTimeout()は効く。
2.Oracle JDBC Driverの接続プロパティ
上述のOracleドキュメントに記載されている、oracle.net.READ_TIMEOUTを試した。だが、1000(1秒)を設定して2分以上経過してもタイムアウトしない。おそらく効いていない。インターネットで色々調べていると、よく似たoracle.jdbc.ReadTimeoutというのを見つけた。実験してみると1000(1秒)を設定して約65秒でタイムアウトした。これにoracle.net.CONNECT_TIMEOUTというのを併用することで両方1秒設定で約6秒でタイムアウトさせることができた。微妙にずれがあるのは、おそらくDBCPがリトライしたりしている分の時間かな？(未確認)
また、上記設定をしていると、DBサーバー、ネットワークが復旧すれば接続もすぐに復旧することが確認できた。
設定方法。JDBC接続設定に以下を記述する。
connectionProperties="oracle.jdbc.ReadTimeout=ミリ秒;oracle.net.CONNECT_TIMEOUT=ミリ秒"
3.SQLNET.EXPIRE_TIME
上記2の設定だけだと、validationQueryだけではなく単純に処理に時間のかかるクエリもタイムアウトしてしまう。これを回避する方法について調査しているとSQLNET.EXPIRE_TIMEというsqlnet.oraのパラメータを見つけた。sqlnet.oraファイルのパラメータによると、Oracleサーバー側のSQLNET.EXPIRE_TIMEに0より大きい値を設定することで、Oracleサーバーからクライアントに対して接続されている接続が生きているか確認するためのプローブパケットを送信し応答がなければ接続を閉じるような動きをする模様。タイムアウト時間内にプローブパケットを送信させることで、タイムアウトを防げるのではないかと考えた。一定時間Sleepするストアドを作成して実際に試したところ、上記2の設定時間を超えてもタイムアウトせずに正常にクエリ実行ができることが確認できた。
ただし、SQLNET.EXPIRE_TIMEを設定すると、Oracleがプローブパケットを送信するかわりにTCP/IP KeepAliveプローブパケットが送信されなくなるという情報をみつけた。*2また、SQLNET.EXPIRE_TIMEのプローブパケット送信は、ステータスがKILLEDのOracleセッションは対象外になるらしい。これらが真実だとすると、上記設定を行うことで、例えば手動でセッションをKILLした場合、Oracleをshutdownしない限り、TCP/IP KeepAliveタイムアウト時間を過ぎてもKILLEDセッションが残り続けてしまうことになるのでは？と心配になり、ALTER SYSTEM KILL SESSIONで実験したところ、30分程度かかったがKILLEDセッションがなくなることを確認した。必ずなくなるのか他に条件があるのかは不明だが、少なくとも必ず残り続けるわけではないことはわかった。また、最悪OS側からプロセスをkillすることも可能。WindowsのOracleはスレッドで動いているのでOS標準機能で特定のスレッドだけkillするのはおそらくできない？が、OTN掲示板*3の書き込みによると、Windows版Oracleにはorakillというコマンドが入っていて、SPIDを指定してkillすることが可能らしい。SPIDはv$processにあるので、v$sessionと結合してステータスがKILLEDのものを検索すればよいはず。
SQLNET.EXPIRE_TIMEの設定方法。サーバーのORACLE_HOME/network/admin/sqlnet.oraに以下を記述する。
SQLNET.EXPIRE_TIME=プローブパケットの送信間隔(分)
まとめ
上記2と3により、実現したいことが達成できた。実際に2と3の設定を行った状態でTomcat <-> Oracle間の通信をDROPしたり、DBサーバーを再起動しても、ネットワークやDBが復旧すると自動的にTomcatからのDB接続が復旧し、Webアプリケーションも動作することが確認できた。
最終的に設定は以下のようにする予定。
Tomcat側
connectionProperties="oracle.jdbc.ReadTimeout=130000;oracle.net.CONNECT_TIMEOUT=130000"
SQLNET.EXPIRE_TIME=1
補足
上記2はThin Driverを使う場合の設定。OCI Driverを使う場合は、実験した限りでは以下の設定で同様のことが可能。上記2の設定もおそらく同等のものと思われる。
APサーバー側のsqlnet.oraに以下の設定を記述する。
SQLNET.OUTBOUND_CONNECT_TIMEOUT=クライアントがDBサーバーへのOracle Net接続を確立する秒数 SQLNET.RECV_TIMEOUT=接続が確立した後にクライアントがDBサーバーからの応答データを待機する秒数
2010/11/11 追記
Tomcatへのアクセス数が少なかったり、ピークは多くても普段は少ないというような場合には、DBコネクションプールのアイドル接続数(maxIdleやminIdle)を小さめにするよう考慮する必要がある。
理由は、プールしている接続が多いとその分だけ復旧に時間がかかるため。上記で「タイムアウトさせることでDBCPでその接続を破棄して再接続させる(testOnBorrowの機能)」と簡単に書いたが、実際には、ValidationQueryでエラーになった(タイムアウトした)場合は、その接続を破棄して別のプールしている接続を取得する。ここまでの挙動はDBCPの公式ドキュメントに記載されている通り。で、その先どうなるのかDBCPのコードを確認してみると、その別のプールしている接続にもValidationQueryを実行し、エラーになった場合は破棄して、さらに別のプールしている接続を取得し、、、ということを繰り返し、最終的にプールしている接続がなくなれば新規に接続し直すという実装になっている。
今回のようにプールしている接続がすべて死んでいる場合、それぞれのValidationQuery実行時に、設定したタイムアウト時間がかかるので、復旧までには、単純計算で、プールしている接続数 x タイムアウト時間の時間がかかってしまう。これはアクセスが1回しかない場合の話で、例えばプールしている接続数分の同時アクセスがくれば、プールしていた接続はすべて同時に検証され同時にタイムアウトして空きがなくなるのですぐに復旧する。上記でアクセス数が少ない場合と書いたのはこのため。
DBCPの設定でtestWhileIdleをtrueにすることで、timeBetweenEvictionRunsMillisの設定間隔で、numTestsPerEvictionRunの数だけ接続の検証が行われるので、これを併用するともう少し復旧を早めることができるはず。ただし、numTestsPerEvictionRunをプール接続数と同じにすればすぐに復旧させられるかと思いきや、実際に試してみるとnumTestsPerEvictionRunに少ない値を指定したときと違いが感じられなかった。DBCPのコードを確認したわけではないが、おそらくtestWhileIdleによる検証はnumTestsPerEvictionRunの数だけ「1つずつ」順次実行しているのではないか。それであれば今回の目的のためには、タイムアウト値よりtimeBetweenEvictionRunsMillisが長くない限り、2以上を設定しても効果はないと思われる。
