---
title: Log4JDBCでSQLログを出力する
tags: []
categories: ["Programming", "Java", "net", "sf", "log4jdbc"]
date: 2011-12-20T13:14:22Z
updated: 2011-12-20T13:14:22Z
---

[Log4JDBC][1]はJDBCにSpyをしかけて、実行するSQL等、JDBC API周りのログを出力させるライブラリです。JDBCレベルに仕込んでいるので上位のフレームワークが何であろうと関係ありません。特にJPA(Hibernate)みたいなSQL自動生成系O/Rマッパーを使っていると、JPQLに慣れないうちは実際にどんなSQLが発行されているのか確認しないと、知らないうちにSQLが大量発行されていて危険だったりします。そんなときにSQLログで実際に発行されるSQLを見ておくと安心。

デバッグ時やトラブル解析用に超有用です。

### 使い方
#### pom
Log4JDBCはmavenレポジトリに登録されていないので、ここではちょっとカスタマイズされた[Log4JDBC-remix][2]を使います(基本設定は同じ)。pom.xmlに

    <dependency>
        <groupId>org.lazyluke</groupId>
        <artifactId>log4jdbc-remix</artifactId>
        <version>0.2.6</version>
    </dependency>

を追加。

Log4JDBCはログファサードにSLF4Jを使っており、その先は好きなものを選びます。個々ではLog4Jを選びます(以下のようなdependencyを追加)。

    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>1.6.2</version>
        <scope>runtime</scope>
    </dependency>
    <dependency>
        <groupId>log4j</groupId>
        <artifactId>log4j</artifactId>
        <version>1.2.15</version>
        <exclusions>
            <exclusion>
                <groupId>javax.mail</groupId>
                <artifactId>mail</artifactId>
            </exclusion>
            <exclusion>
                <groupId>javax.jms</groupId>
                <artifactId>jms</artifactId>
            </exclusion>
            <exclusion>
                <groupId>com.sun.jdmk</groupId>
                <artifactId>jmxtools</artifactId>
            </exclusion>
            <exclusion>
                <groupId>com.sun.jmx</groupId>
                <artifactId>jmxri</artifactId>
            </exclusion>
        </exclusions>
        <scope>runtime</scope>
    </dependency>

#### JDBCドライバの設定変更
ドライバクラス名とurlを変えます。

ドライバのクラス名は`net.sf.log4jdbc.DriverSpy`固定で。実際のドライバは有名どころであれば自動で認識されます。urlは`jdbc:`の後に`log4jdbc:`を追加します。


プロパティファイルに設定している場合の変更例を以下に

    database.username=user
    database.password=password
    #database.url=jdbc\:mysql\://localhost\:3306/bookstore
    database.url=jdbc\:log4jdbc\:mysql\://localhost\:3306/bookstore
    #database.driverClassName=com.mysql.jdbc.Driver
    database.driverClassName=net.sf.log4jdbc.DriverSpy

#### ログの設定

log4j.xmlに以下のような設定を。

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

設定するロガーは

 - jdbc.sqlonly (SQLのログ出力)
 - jdbc.sqltiming (SQLのログ+実行時間出力)
 - jdbc.audit (ResultSet以外のAPIのログ出力。膨大)
 - jdbc.resultset (ResultSetのAPIログ出力)
 - jdbc.connection (Connectionのopen/close時にダンプログ出力。コネクションリーク発見用)

があります。

デフォルトでは90桁で改行される。個人的には一行ログにしたいので、クラスパス直下の`log4jdbc.properties`に以下の設定をする。

    log4jdbc.dump.sql.maxlinelength=0

### 実際に出るログ

Hibernateで以下のようなログが出ていた処理で

    [2011/12/21 00:07:57] [org.hibernate.SQL] [DEBUG] select book0_.book_id as book1_0_2_, book0_.author as author0_2_, book0_.book_name as book3_0_2_, book0_.category_id as category5_0_2_, book0_.price as price0_2_, book0_.publisher_id as publisher6_0_2_, category1_.category_id as category1_1_0_, category1_.category_name as category2_1_0_, publisher2_.publisher_id as publisher1_5_1_, publisher2_.publisher_name as publisher2_5_1_ from book book0_ left outer join category category1_ on book0_.category_id=category1_.category_id left outer join publisher publisher2_ on book0_.publisher_id=publisher2_.publisher_id where book0_.book_id=?
    [2011/12/21 00:07:57] [org.hibernate.SQL] [DEBUG] delete from book where book_id=?

Log4JDBCのログに差し替えると

    [2011/12/21 00:14:52] [jdbc.sqltiming] [DEBUG]  org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
    2. select book0_.book_id as book1_0_2_, book0_.author as author0_2_, book0_.book_name as book3_0_2_, book0_.category_id as category5_0_2_, book0_.price as price0_2_, book0_.publisher_id as publisher6_0_2_, category1_.category_id as category1_1_0_, category1_.category_name as category2_1_0_, publisher2_.publisher_id as publisher1_5_1_, publisher2_.publisher_name as publisher2_5_1_ from book book0_ left outer join category category1_ on book0_.category_id=category1_.category_id left outer join publisher publisher2_ on book0_.publisher_id=publisher2_.publisher_id where book0_.book_id=10001 {executed in 2 msec}
    [2011/12/21 00:14:52] [jdbc.sqltiming] [DEBUG]  org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
    2. batching 1 statements:
    0:  delete from book where book_id=10001 {executed in 2 msec}

な感じに。バインド変数が埋まり、実行時間とどのメソッドから呼ばれたかまでわかります。こうやるとdelete文は実はバッチ実行だったことがわかるなどしてJPAの理解にもつながります(EnityManager#flushを実行した箇所)。。

  [1]: http://code.google.com/p/log4jdbc/
  [2]: http://code.google.com/p/log4jdbc-remix/