こんにちは、鈴木です。
JDBC ドライバが実際に発行している SQL を確認したくなることってありますよね。特にデバッグするときなんかは、「INSERT INTO users (name, age) VALUES (?, ?)」のようにプレースホルダがそのままの状態ではなく、「INSERT INTO users (name, age) VALUES ('たろう', 20)」のような状態で SQL を確認できると、とても嬉しいです。
log4jdbc を使うと JDBC ドライバが発行する SQL をログ出力することができます。log4jdbc は JDBC ドライバをラップして、ログ出力する処理を追加しています。
pom.xml に追加する
Maven を使っているとして、pom.xml に依存ライブラリとして以下を追加します。
|
1 2 3 4 5 6 7 8 9 10 11 12 |
... <dependency> <groupId>com.googlecode.log4jdbc</groupId> <artifactId>log4jdbc</artifactId> <version>1.2</version> </dependency> <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-log4j12</artifactId> <version>1.7.5</version> </dependency> ... |
log4j.properties を作る
log4j.properties を作ります。ファイルにログ出力するようにします。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 |
log4j.rootCategory=INFO, file log4j.appender.file=org.apache.log4j.FileAppender log4j.appender.file.File=development.log log4j.appender.file.layout=org.apache.log4j.PatternLayout log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n # ResultSet に関する呼び出しを除く全ての JDBC の呼び出し log4j.logger.jdbc.audit=DEBUG, file log4j.additivity.jdbc.audit=false # ResultSet に関する呼び出し log4j.logger.jdbc.resultset=DEBUG, file log4j.additivity.jdbc.resultset=false # 実行される SQL log4j.logger.jdbc.sqlonly=DEBUG, file log4j.additivity.jdbc.sqlonly=false # SQL が実行される直前 log4j.logger.jdbc.sqltiming=DEBUG, file log4j.additivity.jdbc.sqltiming=false # コネクションの確立/切断 log4j.logger.jdbc.connection=DEBUG, file log4j.additivity.jdbc.connection=false # log4jdbc 自身のデバッグメッセージ log4j.logger.log4jdbc.debug=OFF, file log4j.additivity.log4jdbc.debug=false |
log4jdbc では出力するログの種類がいくつかていぎされています。（それぞれの役割はコメントで記述しています）。
ログファイルには以下のような内容が出力されます。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
2014-01-03 01:14:34 DEBUG connection:533 - open connections: 2 (1) 2014-01-03 01:14:34 DEBUG audit:158 - 2. Connection.new Connection returned org.springframework.jdbc.datasource.SimpleDriverDataSource.getConnectionFromDriver(SimpleDriverDataSource.java:140) 2014-01-03 01:14:34 DEBUG audit:158 - 2. Connection.getAutoCommit() returned true org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:221) 2014-01-03 01:14:34 DEBUG audit:158 - 2. Connection.setAutoCommit(false) returned org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:226) 2014-01-03 01:14:34 DEBUG audit:158 - 2. PreparedStatement.new PreparedStatement returned org.springframework.jdbc.core.JdbcTemplate$SimplePreparedStatementCreator.createPreparedStatement(JdbcTemplate.java:1559) 2014-01-03 01:14:34 DEBUG audit:158 - 2. Connection.prepareStatement(INSERT INTO users (name, age) VALUES (?, ?) RETURNING id) returned net.sf.log4jdbc.PreparedStatementSpy@94124f org.springframework.jdbc.core.JdbcTemplate$SimplePreparedStatementCreator.createPreparedStatement(JdbcTemplate.java:1559) 2014-01-03 01:14:34 DEBUG audit:158 - 2. PreparedStatement.setString(1, "taro") returned org.springframework.jdbc.core.StatementCreatorUtils.setValue(StatementCreatorUtils.java:373) 2014-01-03 01:14:34 DEBUG audit:158 - 2. PreparedStatement.setObject(2, 20) returned org.springframework.jdbc.core.StatementCreatorUtils.setValue(StatementCreatorUtils.java:384) 2014-01-03 01:14:34 DEBUG sqlonly:221 - org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:701) 2. INSERT INTO users (name, age) VALUES ('taro', 20) RETURNING id 2014-01-03 01:14:34 DEBUG sqltiming:365 - org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:701) 2. INSERT INTO users (name, age) VALUES ('taro', 20) RETURNING id {executed in 11 msec} 2014-01-03 01:14:34 DEBUG resultset:158 - 2. ResultSet.new ResultSet returned org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:701) 2 |
ライブラリやフレームワークを使っていると、中で何が行われているのか見えづらくなってしいがちですが、こうやって実際に発行される SQL を確認できると安心できますね。
