- PR -

DBのgetConnection()に失敗しTomcatが無応答状態になる件

1
投稿者投稿内容
よしお
会議室デビュー日: 2008/10/13
投稿数: 8
投稿日時: 2009-03-13 16:00
こんにちは、お世話になっております。
今回、下記の件ご相談いたしたく、投稿いたしました。

数回、以下のようなメソッドでSQLを実行すると、
Tomcatが完全に応答しなくなるという現象に悩まされています。
仕様変更などがあり、変更前より若干複雑なSQLに変更したのですが、
変更前は、何の問題もありませんでした。

【環境】
・Tomcat6
・Struts2.1
・Spring2.0
・JRE1.6
・Oracle9.2
・Oracle JDBC Driver ojdbc6.jar

【該当メソッド】
public XXXObject select(String id) throws SQLException {
　　　　XXXObject xxxobj = null;

　　　　Connection con = null;
　　　　PreparedStatement pStmt = null;
　　　　ResultSet rs = null;
　　　　StringBuffer strSQL = new StringBuffer();

　　　　// 実際はもっと複雑なSQL
　　　　strSQL.append("SELECT COL1, COL2 FROM DMYTABLE WHERE ID = ? ");

　　　　try {
　　　　　　　　この部分で応答しない。----->>>con = source.getConnection();

　　　　　　　　pStmt = con.prepareStatement(strSQL.toString());

　　　　　　　　pStmt.setString(1, id);

　　　　　　　　rs = pStmt.executeQuery();
　　　　　　　　if(rs.next()) {
　　　　　　　　　　　　xxxobj = getEntityElem(rs);
　　　　　　　　}
　　　　} catch(SQLException e) {
　　　　　　　　throw e;
　　　　} finally {
　　　　　　　　rs.close();
　　　　　　　　pStmt.close();
　　　　　　　　con.close();
　　　　}

　　　　return xxxobj;
}

Tomcatのスレッドダンプを取得してみたところ、下記のような怪しい部分かありました。
DBCPのコネクションプールのサイズが上限(maxActive)に達し、
getConnection()に失敗していることで応答しない状態になっているようです。
どうも、コネクションのリークが発生しているようなのですが、
close()を行っているにもかかわらず、どのような原因でリークが発生するのでしょうか？

【スレッドダンプ抜粋】
"http-8080-2" daemon prio=6 tid=0x05669c00 nid=0x79c in Object.wait() [0x05cdd000..0x05cdfd18]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x2382be00> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:942)
- locked <0x2382be00> (a org.apache.tomcat.dbcp.pool.impl.GenericObjectPool)
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
at 該当メソッドselect
at 該当メソッドselect呼び出し
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)

※以下略


DBCPのコネクションプールのサイズの上限(maxActive)を増やせばいいのですが、
どうも納得できないでいます。
どなたか同じような現象にあわれたかたとかいらっしゃいますか？
少しでもヒントをいただきたく、投稿させていただきました。

[ メッセージ編集済み 編集者: よしお 編集日時 2009-03-13 17:38 ]
デューン
大ベテラン
会議室デビュー日: 2004/04/21
投稿数: 174
お住まい・勤務地: Tokyo
投稿日時: 2009-03-13 16:25
Connection返却してなくて待ち続けてるんじゃないですか？

[ メッセージ編集済み 編集者: デューン 編集日時 2009-03-13 16:25 ]
よしお
会議室デビュー日: 2008/10/13
投稿数: 8
投稿日時: 2009-03-13 16:52
お返事ありがとうございます。

プールにはorg.apache.tomcat.dbcp.dbcp.BasicDataSource(DBCP)というのを利用してるのですが、
Connectionのclose()を呼ぶことがプールへの返却と認識していましたが、
違うのでしょうか？
ジン
ベテラン
会議室デビュー日: 2007/07/27
投稿数: 52
投稿日時: 2009-03-13 18:07
close()で返却します。
実際に待ち状態が続いているのではないでしょうか？


SQL発行のメソッド内でConnectionを取得しているので
ループ処理でSQLを大量に発行してConnectionを大量消費してる？？


他のメッソドでのclose()忘れがある？？


とかは考えられませんか？？
よしお
会議室デビュー日: 2008/10/13
投稿数: 8
投稿日時: 2009-03-13 18:43
お返事ありがとうございます。

おっしゃる通り、スレッドダンプやOracleのv$session表から判断しても、
プールの上限値に達し、新たにコネクションを作成しようとして待ち状態になっているようです。
close()は何度も見直しましたので、おそらくもれはないものと思われます。
また問題は、該当メソッドを意図的に数回呼んだときに発生しますが、
いずれにせよclose()を行っているので、コネクションは返却されると思ったのですが、
どうもうまくいっていないようです。

SQL・参照テーブルの仕様変更（カラム追加）をすると発生することから、
表が変わったことによる負荷が増加した影響がある？のかは、まだ判断できていません。
負荷によって必要コネクションの数が変わってくるというのはあるのでしょうか？
かつのり
ぬし
会議室デビュー日: 2004/03/18
投稿数: 2015
お住まい・勤務地: 札幌
投稿日時: 2009-03-14 11:44
コード:
} catch(SQLException e) {
    throw e;
} finally {
    rs.close();
    pStmt.close();
    con.close();
}

この例外処理では駄目です。
rs.close()に失敗したら、pStmt,conのclose()ができません。
同じく、pStmtのclose()に失敗してもconのclose()はできませんよ。
コード:
} catch(SQLException e) {
    throw e;
} finally {
    try{
        rs.close();
    }catch(SQLException e2){
        //何かログなどの処理
    }
    try{
        pStmt.close();
    }catch(SQLException e2){
        //何かログなどの処理
    }
    try{
        con.close();
    }catch(SQLException e2){
        //何かログなどの処理
    }
}

というようなコードにすると、何があっても必ずcon.close()が呼ばれます。
そういう視点で再度返却忘れがないかを確認してみましょう。
よしお
会議室デビュー日: 2008/10/13
投稿数: 8
投稿日時: 2009-03-15 17:01
お返事ありがとうございます。

その後、解析を進めた結果原因が判明しました。

該当メソッドを実行する際、もう一つ別のメソッドが走るのを見落としていました。
テーブルを変更した際、その別メソッドのSQLにも変更が及んでいましたが、
そちらは実行されていないものと思い込み、無視していました。
かつのりさんのご指摘の通り、その別メソッドSQLが実行不可能なことが原因で、
finally部のcloseに失敗していました。
SQLを正しく変更し、メソッドのエラー処理部を修正した結果、症状がなくなりました。

この、もう一つの別メソッドに気づけなかったため、原因判明までに時間がかかりました。
プールの接続リーク対策を行う際の、ログ出力が役に立ちました。
下記のページを参考にしました。
http://www.ksky.ne.jp/~snbhsmt/commons-dbcp.html

初歩的なミスでしたが、エラー処理もなかなか奥が深いです。。。
アドバイスをいただきました皆さんに、心から感謝いたします。
ありがとうございました。
1

スキルアップ／キャリアアップ（JOB@IT）