数百キロのコードでブルー - ドクターTomcat緊急救命：現場から学ぶWebアプリ開発のトラブルハック（14）（2/2 ページ）

» 2010年05月25日 00時00分公開

■ステップ【3】コネクションプールのリーク検出機能を試す

　幸い、最近のコネクションプールには、コネクションの解放漏れを検出する機能を持つものがある。今回のシステムでは、TomcatのDBCPによるコネクションプールが利用されており、DBCPはコネクションの解放漏れを検出できる。

　「context.xml」に次のように記述することにより、コネクションの解放漏れが発生した際にメッセージをログに出力するようになる。

 <Resource name="jdbc/postgres" auth="Container"
           type="javax.sql.DataSource"
           driverClassName="org.postgresql.Driver"
           url="jdbc:postgresql://127.0.0.1:5432/tomcat"
           username="xxx" password="xxx"
           maxActive="20" maxIdle="10" maxWait="-1"
           　removeAbandoned="true"  removeAbandonedTimeout="300" logAbandoned="true"
  />

　上記の設定を行った後、アプリケーションを再起動すると、次のメッセージがログメッセージに追加され、コネクションの解放漏れを検出できるコネクションプール（AbandonedObjectPool）が利用されていることが確認できる。

AbandonedObjectPool is used (org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool@4fc156)
   LogAbandoned: true
   RemoveAbandoned: true
   RemoveAbandonedTimeout: 300

　しばらくアプリケーションを動作させすると、次のようなスタックトレースがログに出力され、コネクションの解放漏れが検出された。

DBCP object created 2010-05-01 08:16:19 by the following code was never closed:
java.lang.Exception
	at org.apache.tomcat.dbcp.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java:160)
	at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:86)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
	at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
	　at org.ultimania.servlet.ConnectionManager.getConnection(ConnectionManager.java:17)
	　at org.ultimania.servlet.ItemManager.service(ItemManager.java:29)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:852)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
	at java.lang.Thread.run(Unknown Source)

　このログの7～8行目の部分を見ると、「ConnectionManager」というクラスのgetConnection()メソッドで取得されたコネクションがコネクションの解放漏れを発生させていることが確認できる。ConnectionManager.getConnection()メソッドと、それを呼び出しているItemManager.service()メソッドを調査することにより、問題を修正できた。

予防処置 - 愛と勇気だけではシステムはよみがえらない

　今回コネクションリークが発生しているコードを見ていると、あることに気が付いた。コネクションの解放漏れが発生しているコードは、次のように記述されている場合が多い。

    // コネクション取得
    Connection con = null;
    try {
        ds = (DataSource)(new InitialContext.lookup("....");
        con = ds.getConnection();
    } catch (NamingException e){
        //エラー処理
…【略】…
 
      } catch (SQLException e){
        //エラー処理
…【略】…
 
    }
 
    //トランザクション処理など業務ロジック
…【略】…
 
    // コネクションクローズ処理
    try {
        con.close();
    } catch (SQLException e) {
        // エラー処理
…【略】…
 
    }

　上記のコードは、一見取得したコネクションを確実にクローズしているように見える。しかし、途中の処理の部分で例外をスローした場合、コネクションはクローズされない。下記のようにコネクションを取得するtry句の中でコネクションの取得とトランザクション処理を行い、finally句の中でクローズを行った方が確実である。

    Connection con = null;
    try {
        ds = (DataSource)(new InitialContext.lookup("....");
        con = ds.getConnection();
  
    //トランザクション処理など業務ロジック
…【略】…
 
    } catch (NamingException e){
        // エラー処理
…【略】…
 
    } catch (SQLException e){
        // エラー処理
…【略】…
 
    } finally {
        if (con!=null) {
            con.close();
        }
    }