JDBCのロギング

データベースを使用したアプリケーションを作成していると、実行されているSQLや、その実行時間を把握したいことがあります。また、JDBCのコネクションリークなどのデバッグ時にはJDBC呼び出しをトレースしたくなります。

実行されているSQLはソースコードからも、ある程度把握可能ですが、動的なSQL文などを多用している場合などは少々面倒です。

log4jdbc

log4jdbcを使用すると、既存ソースを変更せずにSQL文やJDBC呼び出し、実行時間などをログに収集することが可能になります。同様のJDBCドライバにはP6SPYがあります。

log4jdbcのセットアップ

以下は Tomcat5.5 で動作している webアプリケーションにおける log4jdbc のセットアップ手順です。データベースは PostgreSQL を使用しています。

バイナリのダウンロード
log4jdbcのバイナリと依存ライブラリのSLF4Jをダウンロードします。この例では Logbackを使用しますので、そちらもダウンロードします。

この例では

  • log4jdbc-1.1alpha2
  • slf4j-1.4.3
  • logback-0.9.8

のバージョンを使用しました。

jarファイルのコピー
${catalina.home}/common/lib に以下のjarファイルをコピーします。 

log4jdbc3-1.1alpha2.jar
slf4j-api-1.4.3.jar
logback-core-0.9.8.jar
logback-classic-0.9.8.jar

JNDIデータソースの設定変更
データソースを本来のJDBCドライバ(この例ではPostgreSQL)から log4jdbcに変更します。以下は変更前の設定です。

<Resource name="jdbc/postgres" auth="Container"
    type="javax.sql.DataSource"
    driverClassName="org.postgresql.Driver"
    url="jdbc:postgresql:testdb"
    username="testdb"
    password="testdb"
    maxActive="10"
    maxIdle="3"
    maxWait="-1"
    defaultAutoCommit="false" />

以下は変更後の設定です。

<Resource name="jdbc/postgres" auth="Container"
    type="javax.sql.DataSource"
    driverClassName="net.sf.log4jdbc.DriverSpy"
    url="jdbc:log4jdbc:postgresql:testdb"
    username="testdb"
    password="testdb"
    maxActive="10"
    maxIdle="3"
    maxWait="-1"
    defaultAutoCommit="false" />

上記のように driverClassNameが "net.sf.log4jdbc.DriverSpy"に、urlが本来のurlの先頭に "jdbc:log4" を付加したものになります。

Logbackの設定
${webapp.root}/WEB-INF/classes/logback.xml ファイルを作成し、ログ出力の設定を行います。

<configuration>

    <appender name="FILE"
        class="ch.qos.logback.core.FileAppender">
        <file>${catalina.base}/logs/jdbc.log</file>

        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %date %logger %msg%n
            </Pattern>
        </layout>
    </appender>

    <logger name="jdbc.sqltiming">
        <level value="info" />
    </logger>

    <root>
        <level value="off" />
        <appender-ref ref="FILE" />
    </root>

</configuration>

以上で設定は完了です。log4jdbcのログレベルやカテゴリの詳細は log4jdbcのサイトで確認してください。Logbackの設定は Logbackマニュアルを確認してください。

ログ出力の確認

以下のテストプログラムを実行し、ログ出力を確認します。(エラー処理は無視)

Context c = new InitialContext();
DataSource ds = (DataSource)c.lookup("java:comp/env/jdbc/postgres");
Connection conn = ds.getConnection();
PreparedStatement pstmt = conn.prepareStatement(
    "select * from emp");
ResultSet rs = pstmt.executeQuery();

以下のようにログが出力されます。実行時間(この例では 2msec)も取得できています。 

2007-10-07 09:20:39,647 jdbc.sqltiming select * from emp  {executed in 2 msec}

バインド変数を使ったSQL

log4jdbcはバインド変数を使ったSQLを自動的に展開してロギングします。以下はプログラム例です。

PreparedStatement pstmt = conn.prepareStatement(
    "select * from emp where empno = ?");
pstmt.setInt(1, 7369);
ResultSet rs = pstmt.executeQuery();

ログは以下のようになります。 

2007-10-07 09:25:19,987 jdbc.sqltiming select * from emp where empno = 7369  {executed in 2 msec}

この機能のおかげで、収集したSQL文から実行計画を取得する作業(Oracleのexplain planやPostgreSQLのexplain analyzeなど)が非常に簡単になります。

JDBC呼び出しのトレース

log4jdbcには jdbc.sqlonly, jdbc.sqltiming, jdbc.audit, jdbc.resultsetのログカテゴリがあり、それぞれのログレベルを調整することで様々なデータを収集可能になります。詳細はlog4jdbcのサイトで確認してください。

以下はJDBC呼び出しをトレースするための logback.xml の設定例です。

<logger name="jdbc.audit">
    <level value="info" />
</logger>

この設定により、以下のようなログを取得可能になります。 

2007-10-07 09:49:04,540 jdbc.audit 2. Connection.getAutoCommit() returned true
2007-10-07 09:49:04,541 jdbc.audit 2. Connection.setAutoCommit(false) returned
2007-10-07 09:49:04,541 jdbc.audit 2. Connection.prepareStatement(select * from emp where empno = ?) 
    returned net.sf.log4jdbc.PreparedStatementSpy@1318b
2007-10-07 09:49:04,541 jdbc.audit 2. PreparedStatement.setInt(1, 7369) returned
2007-10-07 09:49:04,544 jdbc.audit 2. PreparedStatement.executeQuery() returned
    net.sf.log4jdbc.ResultSetSpy@5bb966
2007-10-07 09:49:04,544 jdbc.audit 2. PreparedStatement.close() returned
2007-10-07 09:49:04,544 jdbc.audit 2. Connection.isClosed() returned false
2007-10-07 09:49:04,544 jdbc.audit 2. Connection.getAutoCommit() returned false
2007-10-07 09:49:04,544 jdbc.audit 2. Connection.isReadOnly() returned false
2007-10-07 09:49:04,545 jdbc.audit 2. Connection.rollback() returned
2007-10-07 09:49:04,545 jdbc.audit 2. Connection.clearWarnings() returned
2007-10-07 09:49:04,545 jdbc.audit 2. Connection.getAutoCommit() returned false
2007-10-07 09:49:04,546 jdbc.audit 2. Connection.setAutoCommit(true) returned
JSPWiki