Quick Start to tracing JDBC SQL operations using log4jdbc

Keywords:
database logging show SQL log4jdbc tomcat JNDI log4j trace performance timing

Problem:
Given a complex web application (with many moving parts), there's performance issues that first impressions seem to point at environment-specific database latency. Is there any way to trace/profile/monitor all the SQL statements being made to the database (preferably with timings)?

Solution:
log4jdbc seamlessly lets you configure a logger between your application and the JDBC connection. Documentation on the log4jdbc site is very good and has just about all you need to know, below is a "quick start" for the impatient.

Step 1: Jar File(s)

Drop the log4jdbc4-[version].jar file into [webapp]/WEB-INF/lib.
You'll also need:

• a supported logging framework (log4j: log4j-[version].jar)
• the SLF4J API (slf4j-api-[version].jar - already had it)
• the SLF4J jar to use this logging framework (slf4j-log4j12-[version].jar - already had it)

Step 2: Driver Class and URL

1. Change the database resource definition to use the driver class net.sf.log4jdbc.DriverSpy ('spy' as it will work out the correct 'real' driver class to use).
   
2. Simply prepend jdbc:log4 to the existing URL.

For a PostgreSQL database connection configured as a JNDI/JDBC Resource in Tomcat, this will look like:

    <Resource
            name="jdbc/example"
            type="javax.sql.DataSource"
            factory="org.apache.tomcat.dbcp.dbcp.BasicDataSourceFactory"
            driverClassName="net.sf.log4jdbc.DriverSpy"
            url="jdbc:log4jdbc:postgresql://localhost:5432/example"
            username="postgres" password="***" 
            maxActive="20" maxIdle="10" maxWait="-1" 
            removeAbandoned="true" removeAbandonedTimeout="120" logAbandoned="true"
            auth="Container"
            charset="UTF-8" />

Step 3: Logging Config

There's detailed notes on the five key loggers and an example log4j.properties is available. But if you just want to see SQL + timings, the following will log this all to console:

log4j.logger.jdbc.audit=FATAL,Log4JDBC
log4j.additivity.jdbc.audit=false

log4j.logger.jdbc.resultset=FATAL,Log4JDBC
log4j.additivity.jdbc.resultset=false

log4j.logger.jdbc.sqlonly=FATAL,Log4JDBC
log4j.additivity.jdbc.sqlonly=false

log4j.logger.jdbc.sqltiming=INFO,Log4JDBC
log4j.additivity.jdbc.sqltiming=false

log4j.logger.jdbc.connection=FATAL,Log4JDBC
log4j.additivity.jdbc.connection=false

log4j.appender.Log4JDBC=org.apache.log4j.ConsoleAppender
log4j.appender.Log4JDBC.layout=org.apache.log4j.PatternLayout
log4j.appender.Log4JDBC.layout.ConversionPattern=%-5p [%d{DATE} %c]: %m%n

That's it. Start up the application and it should function exactly as it did before, but all SQL operations (made via the JNDI connection pool resource in my example) will be logged in the form:

INFO  [01 Nov 2013 12:00:00,000 jdbc.sqltiming]: SELECT NAME FROM PERSON WHERE ID=54321
{executed in 1 msec}

Notes:

Bonus Step: Trace back to the Application Code

If your issue is working what part of the application code triggered the execution of a given SQL statement, a neat feature of the log4jdbc loggers is including the class & method-name of the code that invoked the JDBC driver. As there may be a few layers between your code and the JDBC driver (hibernate > application server connection pool, etc) you can tell it what level you what to capture from.

1. change log level to DEBUG
log4j.logger.jdbc.sqltiming=DEBUG,Log4JDBC
   
2. set the system property log4jdbc.debug.stack.prefix
-Dlog4jdbc.debug.stack.prefix=com.example
   

Log statements will then be in the form:

DEBUG [01 Nov 2013 12:30:00,000 jdbc.sqltiming]:  com.example.PersonDAO.findPerson(PersonDAO.java:111)
2. SELECT NAME FROM PERSON WHERE ID=54321
{executed in 53 msec}

NB: this extra logging adds a noticeable overhead to the database usage (and timings).