Log4JDBCでSQLログを出力する

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

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

使い方

pom

Log4JDBCはmavenレポジトリに登録されていないので、ここではちょっとカスタマイズされたLog4JDBC-remixを使います(基本設定は同じ)。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を実行した箇所)。。

IK.AM