Seeing the complete SQL generated by your Java app

Whatever framework you're using for connection to the DB, or indeed using plain JDBC, viewing the full SQL that the app is sending to the database, and by full, I mean full SQL including the values, is hidden, forcing you to either guess what the complete SQL is, or succumb to using heavy GUI tools to get a hold of that darned SQL statements.

However, there's a tried and tested library called log4jdbc` which gives us what we often want: the possibility to log all the actual SQL produced by the database layer and view this in plain sight without having to fire up a memory hogging beast of a database viewer.

In my experience, this is a little known gem, so I thought I'd write up how to get it working, so can see just how easy it is and make your application that much more transparent.

Put the log4jdbc driver on the app server class path

I'm using Tomcat 7 at the moment, so this means a quick cp to Tomcat's lib directory:

$ cp log4jdbc-*.jar /opt/tomcat-engine/lib

Configure your app server to use the log4jdbc spy driver

For Tomcat 7, this involved two changes: changing the driver name and changing the JDBC URL inside the <Resource/> element where I've configured the database handles:

First, prepaent log4jdbc to the JDBC string:

+        url="jdbc:log4jdbc:mysql://localhost:3306/mydb"
-        url="jdbc:mysql://localhost:3306/mydb"

Then, set the driver class name to be the lg4jdbc spy driver:

+        driverClassName="net.sf.log4jdbc.DriverSpy"
-        driverClassName="com.mysql.jdbc.Driver"

Turn on logging on the log4jdbc classes

For Escenic Content Engine, we're using log4j, which is by default located at /etc/escenic/engine/common/trace.properties:

######################################################################
# sql logging
log4j.appender.SQL=org.apache.log4j.RollingFileAppender
log4j.appender.SQL.File=/var/log/escenic/${com.escenic.instance}-sql
log4j.appender.SQL.MaxFileSize=100MB
log4j.appender.SQL.MaxBackupIndex=1
log4j.appender.SQL.layout = org.apache.log4j.PatternLayout
log4j.appender.SQL.layout.ConversionPattern = %d [%t] %-5p %c- %m%n

log4j.category.jdbc.sqlonly=DEBUG, SQL
log4j.category.jdbc.sqltiming=ERROR, SQL
log4j.additivity.jdbc=false

I'm using a rolling file appender to rotate on size rather than a daily one that I normally use. This is because it fills up pretty quickly, easily reaching hundreds and gigabytes worth of log data.

You just need one of the two loggers. The sqltiming has the same information as sqlonly, with the added benefit of seeing the time each query took.

Filtering of SQL statements

It's possible to tweak which kinds of SQL statements are being logged by setting any of these to JVM parameters true or false. Default is false.

• log4jdbc.dump.sql.select
• log4jdbc.dump.sql.insert
• log4jdbc.dump.sql.update
• log4jdbc.dump.sql.delete
• log4jdbc.dump.sql.create

For Escenic Content Engine, this means editing e.g. /etc/escenic/ece-engine1.conf and setting the following to turn off SELECT statements:

JAVA_OPTS="
  ${JAVA_OPTS}
  -Dlog4jdbc.dump.sql.select=false
"

All the logs you can muster

With this in place and after restarting Tomcat (Escenic users do ece restart), you now have a new log file with all the SQL statements, in full, including all the values and whatever non-sense your database framework has added to your queries (yes, you can even see what Hibernate has done to your simple bean query)

Enjoy!