A couple of years ago I began developing in Java, and my first Java project required that I also learn SQL. Our project team was using mostly EJBs for database access, although for some performance-critical sections of the application we wrote the JDBC logic directly. A problem that we faced regularly was tracking the bind parameters to our PreparedStatements. Over the course of the project, all of the team members tried different techniques to determine what our JDBC statements were actually doing.

This article presents a solution that one of the developers created to help solve this problem. I took his original idea and extended it after I left that team to help my next company solve the same problem. The solution is a JDBC driver that uses log4j to print all SQL statements and any bound parameters to the application's log file.

Most JDBC developers have faced the problem of having to debug SQL statements in their applications. While this sounds like a relatively easy task, it's often error-prone, and results in code that is hard to maintain and that clutters otherwise clean application logic. An example of this type of logic is:

PreparedStatement ps = conn.prepareStatement("Select * from users " + "where id = ?");
log.debug("Select * from users where id = ?");
ps.setInt(1, x);
log.debug("1: " + x);

This solution has some obvious problems. The first problem is that you have duplicated all of the bind parameters and the SQL statement in the code. If either the SQL statement or the parameter that you want to bind to the statement changes, you must remember to update the log statement as well. If you forget to update either log statement, your log will be useless when you try to debug your next problem. Also, because of the performance of using log.debug, most people put those statements in an if block, making the code that much harder to read.

The next problem with this model is that you don't have a centralized location to enable debug logging. When a QA developer reports a bug that you have never seen in your dev testing, the best place to start is to enable more detailed logging to determine what is going wrong. With the above code, you must either enable all debug logging, which is often data overload, or you need to debug the problem enough to determine which class is causing the problem.

The final problem with this system is most important when using a system like Hibernate. Hibernate is an object-relational mapping tool that also defines its own SQL-like language, HQL. The problem with this is that in your Java code, you don't have access to the actual SQL statement that is executed; you only have the HQL statement. In a previous job, we had a problem like this. The SQL statement translated to:

Select * from Sessions where id = ? and subId = ? and user = ? and list = ?

The developer using this statement spent days poring over this query trying to determine why it wasn't returning any data when we expected a list with 10 elements in it. The final answer turned out to be that the final bind parameter was being passed in as NULL. Since the details of the SQL statement had been abstracted out by HQL, this problem wasn't clear. We discovered this by accident after reading the log file as a group. The rest of this article will focus on a better answer that would have shown us the problem immediately.

The Logging JDBC Driver
The idea behind this project has some concepts in common with aspect-oriented programming (AOP). The basic thought process is that there are some problems that are found throughout a project, and the solution to those problems shouldn't require programmers to remember to add special logic every time one of these problems comes up. Instead, the programming framework that you are using should create solutions to these problems for you. In this case, our problem is determining exactly what SQL queries are being run and with which parameters.

Working to our advantage with SQL queries, they all must go through a JDBC driver, so if we can find a way to log the correct information in the driver, the rest of the application won't have to change. That is the goal of the logdriver, available at www.rkbloom.net/logdriver under the Apache 2.0 License.

The driver currently logs comprehensive debug information for Statements, PreparedStatements, and CallableStatements and some important actions on the Connection. The primary data being logged is the SQL query and any bind parameters. There are two formats that can be used. The first separates the SQL from the bind parameters:

executing PreparedStatement: 'insert into ECAL_USER_APPT
(appt_id, user_id, accepted, scheduler, id) values (?, ?, ?, ?, null)'
     with bind parameters: {1=25, 2=49, 3=1, 4=1}

The second format is enabled by setting the system property replace.bindParams to either 1or true. This format tries its best to insert the bind parameters into the SQL query:

executing PreparedStatement: insert into ECAL_USER_APPT
(appt_id, user_id, accepted, scheduler, id) values (25, 49, 1, 1, null)

Both formats have their advantages, but most of the time it's better to use the default format. The biggest argument against using the second format is that for string parameters the logging driver doesn't attempt to escape the string. While this isn't a security concern at all, it does make it harder to read the SQL and understand it correctly. The format is similar for CallableStatements, but the driver includes information about the type of the parameter.

Configuring the Logging Driver
Configuration of this driver is relatively straightforward. Instead of using your standard JDBC driver, configure your application to use net.rkbloom.logdriver.LogDriver, and your connection URL should be changed to use the following format:

jdbc:log:real_driver_class:real_jdbc_connection_string

If your original connection URL was "jdbc:oracle:thin:@ local-host:1521:FOOBAR", your new URL would be: "jdbc:log:com.oracle.jdbc.OracleDriver:oracle:thin:@localhost:1521:FOOBAR". The logdriver.jar file must be on your classpath, but so must the JAR file with the original JDBC driver. Under the covers, the logDriver will create an instance of your desired JDBC driver and call it for all operations. With just that change your application will be using the logDriver, but you won't see any log messages by default.

To enable logging, you must configure the logging system. The logDriver uses log4j for all logging, so you will need to configure your log4j.properties file to log all net.rk-bloom.logdriver classes to log in debug mode. The log-Driver uses debug mode for all logging because of the performance implications of doing so much logging. It would be possible to modify the driver to use either commons-logging or the java.util.logging, but I only use log4j, so I went for the easiest solution.

Advantages of the Driver
I have used this driver beyond just debugging my SQL queries when applications don't behave as I expect. When using Hibernate, I have found that many developers don't understand how many queries a simple query can invoke. By enabling the logDriver, I have been able to isolate performance problems in my Hibernate-based applications and use that information to modify my mapping files to reduce the number of SQL queries used.

Because the logDriver intercepts all SQL queries regardless of how they are invoked, I have found this solution to work better than the options that Hibernate provides. In most of my DB applications, I use a combination of either EJBs or Hibernate with direct JDBC calls. By moving the logging into a single location, I am able to track all SQL interaction with a single configuration change. This can be invaluable when QA reports a bug that can't be explained quickly.

Limitations with the System
For all of the benefits of the logDriver, there are a few limitations. First, you can't enable logging of SQL statements on a per-class basis. Ideally, you would be able to configure the logDriver to log queries for the Foo class, but not the Bar class. If the log statements were embedded in the classes, this would be possible with any of the logging systems; however, since the logging statements are in a common class, it can't be done natively. One possible solution to this is to include a configuration system for the logDriver that would allow the driver to inspect the call stack to determine if the logging statements should be executed. Because this system is intended for developers, it's easier to ask developers to isolate the methods called.

The second limitation is that this solution has a big impact on performance. The more DB operations you perform, the slower this driver performs. This makes sense, because logging is always a potential performance problem for Java applications, and the point of this solution is to log a lot of data. While logging can slow down the application, again this solution is intended for development, not production, so performance should not be a big consideration.

The final limitation is that we cannot log the results of the queries. The problem is that not all ResultSets are rewindable, so if we try to log the ResultSet, it is possible that we will consume the data, making it unusable for the application. While logging that data would be useful, the implications of doing so make it impractical.

Conclusion
I hope that I have shown you a new way to debug and solve DB problems in your Java applications. I would like to thank Jonathan Cobb for creating the original version of this driver, which inspired me to re-create it when I began to encounter similar problems.