Log4jdbc: Logging JDBC activity and SQL queries

In an application that frequently queries a database it is important to know what is happening now, how often this or that query occurs and how long it takes to get result. Log4jdbc allows to log database activity e.g. SQL queries, processing time, result sets, connection usage.

Log4jdbc creates a JDBC Proxy. Every SQL request is intercepted, logged with SLF4J and passed back to real JDBC driver.  

So why and when do we need to log database activity? Many ORM frameworks e.g. Hibernate allow you to show SQL when running in debug mode.

To see what Hibernate is doing with your database, just add these parameters to your Hibernate configuration:

<property name="show_sql">true</property>
<property name="format_sql">true</property>

The following output will be generated by Hibernate logger:

DEBUG org.hibernate.SQL  - select deliveryre0_.id as id1_, deliveryre0_.callback_reference_id as callback2_1_, deliveryre0_.client_correlator as client3_1_, deliveryre0_.client_id as client4_1_, deliveryre0_.created as created1_, deliveryre0_.last_status_change as last6_1_, deliveryre0_.status as status1_, deliveryre0_.sender_address as sender8_1_ from delivery_report_notification deliveryre0_ where deliveryre0_.client_id=? and deliveryre0_.client_correlator=?

The disadvantage of these debug records is that they show PreparedStatements with placeholders instead of real values. It is certainly possible to debug parameter bindings in Hibernate, but the output is unnecessary verbose:

Hibernate: INSERT INTO table (ID, DATE, PRICE) VALUES (?, ?, ?)

10:13:05,129 DEBUG IntegerType:133 - binding '1' to parameter: 1
10:13:05,133 DEBUG DateType:133 - binding '14 October 2012' to parameter: 2
10:13:05,134 DEBUG FloatType:133 - binding '3.75' to parameter: 3

The output generated by Log4jdbc is more useful, it show a real query that is passed into database with real values:

INFO  jdbc.sqltiming  - select deliveryre0_.id as id1_, deliveryre0_.callback_reference_id as callback2_1_, deliveryre0_.client_correlator as client3_1_, deliveryre0_.client_id as client4_1_, deliveryre0_.created as created1_, deliveryre0_.last_status_change as last6_1_, deliveryre0_.status as status1_, deliveryre0_.sender_address as sender8_1_ from delivery_report_notification deliveryre0_ where deliveryre0_.client_id=2 and deliveryre0_.client_correlator='ALPHABETA' {executed in 1 msec}

This was an example of the jdbc.sqltiming logger. Log4jdbc has several loggers that can be used e.g. to track connection usage:

• jdbc.sqlonly - Logs only SQL. SQL executed within a prepared statement is automatically shown with it's bind arguments replaced with the data bound at that position, for greatly increased readability.
• jdbc.sqltiming - Logs the SQL, post-execution, including timing statistics on how long the SQL took to execute.
• jdbc.audit - Logs ALL JDBC calls except for ResultSets. This is a very voluminous output, and is not normally needed unless tracking down a specific JDBC problem.
• jdbc.resultset - Even more voluminous, because all calls to ResultSet objects are logged.
• jdbc.connection - Logs connection open and close events as well as dumping all open connection numbers. This is very useful for hunting down connection leak problems.

Logback configuration

<logger name="jdbc.sqlonly" level="OFF" additivity="false" />
<logger name="jdbc.sqltiming" level="INFO" additivity="false">
  <appender-ref ref="DATABASE_LOG_FILE" />
</logger>
<logger name="jdbc.audit" level="OFF" additivity="false" />
<logger name="jdbc.resultset" level="OFF" additivity="false" />
<logger name="jdbc.connection" level="OFF" additivity="false" />
<logger name="jdbc.resultsettable" level="OFF" additivity="false" />
<logger name="log4jdbc.debug" level="OFF" additivity="false" />

Log4jdbc is not available on Maven central repository, so you have to download it manually. Log4jdbc is available on Google Code at http://code.google.com/p/log4jdbc/. You can download its source codes or jars for JDBC 3 or 4.

Good news

There is an experimental fork called log4jdbc-remix, that solves some of the Log4jdbc problems. It is available on Maven central repository:

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

Also you can use it in Spring as a datasource.

<bean id="dataSourceSpied" class="...">
  <property name="driverClass" value="${datasource.driverClassName}"/>
  <property name="jdbcUrl" value="${datasource.url}"/>
  <property name="user" value="${datasource.username}"/>
  <property name="password" value="${datasource.password}"/>
  ...
</bean>

<bean id="dataSource" class="net.sf.log4jdbc.Log4jdbcProxyDataSource">
  <constructor-arg ref="dataSourceSpied" />
</bean>

Log4jdbc-remix is available on Google Code at http://code.google.com/p/log4jdbc-remix/