使用log4jdbc輸出SQL語法

簡介

若是在專案開發與偵錯的過程中，難免都會遇到希望列印完整的SQL Command(及prepare statement的value)，這類的solution筆者用過的有P6SPY(https://github.com/p6spy/p6spy)與log4jdbc(https://code.google.com/p/log4jdbc/)，本文介紹其中的log4jdbc。

使用方式(以1.2版為例)

Step 1. 先確認使用的JDK搭配的JDBC版本

• 若為JDK 1.4 or 1.5，請使用搭配的JDBC 3的log4jdbc3-1.2.jar
• 若為JDK 1.6以上版本，請使用搭配的JDBC 4的log4jdbc4-1.2.jar

請注意，不是用jdbc driver本身是type 3 or 4來判斷的！

Step 2. 選擇輸出日誌的框架

log4jdbc是使用SLF4J的Simple Logging Facade來輸出log的，但如同SLF4J，也可以支援log4j, java.util.logging, Apache Commons Logging, Logback。以筆者用的log4j為例，使用時要在classpath內增加以下jar擋：

• slf4j-api-1.6.0.jar
• slf4j-log4j12-1.6.0.jar

Step 3. 將jdbc driver的class name改為net.sf.log4jdbc.DriverSpy

如：

jdbc.driverClass=net.sourceforge.jtds.jdbc.Driver

改寫為：

jdbc.driverClass=net.sf.log4jdbc.DriverSpy

Step 4. 改寫jdbc url，將jdbc:XXXX改為jdbc:log4jdbc:XXX

如：

jdbc.jdbcUrl=jdbc:jtds:sqlserver://localhost:1433/app4use;instance=SQLEXPRESS

改寫為：

jdbc.jdbcUrl=jdbc:log4jdbc:jtds:sqlserver://localhost:1433/app4use;instance=SQLEXPRESS

Step 5. 修改log設定檔案，顯示log4jdbc的訊息

log4jdbc共有以下5個logger可供設定，每一個logger皆可以設定ERROR, INFO, DEBUG層級(FATAL表示關閉)：

• jdbc.sqlonly : 顯示執行的SQL Command
• jdbc.sqltiming : 顯示執行的SQL Command及其耗費時間(若開啟此logger，則jdbc.sqlonly可以不用開)
• jdbc.audit : 顯示除了resultset之外的所有JDBC Calls，會產生大量的log內容
• jdbc.resultset : 顯示resultset的內容，會產生更大量的log內容
• jdbc.connection : 顯示DB Connection的open, close, commit等事件發生的log，在追查connection pool調度問題時相當有用

log4j.properties範例如下：

log4j.rootLogger=INFO, stdout

log4j.logger.jdbc.sqlonly=FATAL, stdout
log4j.logger.jdbc.sqltiming=INFO, stdout
log4j.logger.jdbc.audit=FATAL, stdout
log4j.logger.jdbc.resultset=FATAL, stdout
log4j.logger.jdbc.connection=INFO, stdout

log4j.additivity.jdbc.sqlonly=false
log4j.additivity.jdbc.sqltiming=false
log4j.additivity.jdbc.audit=false
log4j.additivity.jdbc.resultset=false
log4j.additivity.jdbc.connection=false

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p [%t] (%c:%L) - %m%n

執行結果範例

 15:48:12,939  INFO [schedulerFactoryBean_Worker-3] (jdbc.connection:537) - 41. Connection opened
15:48:12,939  INFO [schedulerFactoryBean_Worker-3] (com.tstartel.estore.service.impl.MailMessageRecServiceImpl:126) - doImportJobErrorRec() - start
15:48:12,963  INFO [schedulerFactoryBean_Worker-3] (jdbc.sqltiming:370) - insert into mail_message_rec (mail_from, mail_to, mail_cc_to, subject, mail_type, send_type,
status, expected_sending_time, actual_sending_time, send_numbers, is_attachment, message_content_path,
message_content, create_time) values ('webmaster@company.com.tw', 'user@company.com.tw', '出貨接收回覆作業失敗', NULL, NULL, 10, NULL, NULL, 0, NULL, NULL,
'介接系統：<br />作業名稱：出貨接收回覆作業<br />發生時間：2015/10/20 15:48:11<br />Message：com.jcraft.jsch.JSchException:
java.net.ConnectException: Connection timed out: connect<br />', '10/20/2015 15:48:11.657')
 {executed in 1 msec}
15:48:12,968  INFO [schedulerFactoryBean_Worker-3] (jdbc.connection:556) - 41. Connection closed