Oracle JDBC Logging

During a database upgrade (oracle 10g to 11g) I had to debug a series of JDBC calls. I suspected a performance bottleneck in a database query and decided to look for the offending SQL statement.  This is when I started to find how much information there is about JDBC logging. Most places I researched pointed me to p6spy, a nice tool which according to the documentation "intercepts and optionally modifies database statements". This was helpful to determine that the bottleneck was not a SQL statement from our application, but instead a library (open source) which needed metadata information.

P6spy is very useful to determine time and statistics only on Statement calls (and its subclasses). This is done by wrapping these types of objects and gathering statistics around each call. This is possible because of the abstraction provided by JDBC over SQL statements can be replicated by p6spy and then delegated back to the driver of choice. As we installed and run p6spy, we proved it was helpful to confirm what we suspected: Our application was just fine, the new database (11g) was having problems. Furthermore, we were able to detect that the offending API call was the following:

DatabaseMetadata md = connection.getMetadata();
md.getTables();

This type of JDBC call was not something we have control over. Now, most DBAs will demand to know the SQL query causing the slow performance in order to debug it and see what kind of improvements can be done to it. This is something very peculiar because no developer has a chance to change the query generated by the snippet above (this is part of the JDBC driver, specific to oracle). In fact, p6spy will not help either as this is not even a wrapper over Statement calls (well, it really is as you may learn later, but that's beyond the point of this subject). We decided to look into JDBC logging.

Enabling logging in JDBC is a very subtle feature of JDBC, yet a powerful one. There is the ability to add a PrintWriter to your DriverManager. This partially helps and really is of no use if you are trying to look into the internals of the JDBC API. With a bit more of research, we learned about the debugging version of the JDBC driver. It contained logging using the java.util.logging framework. As I worked with this Oracle driver, the following worked only with the proper ojdbc version.

1. Ensure that you use jdbc5_g.jar (java 5) or jdbc6_g.jar (java 6). This is very important as these drivers contain debugging (and logging) information.
2. Ensure no other JDBC driver is used.
3. Add the following system properties: -Doracle.jdbc.Trace=true
4. Have a properties file with the logging configuration. A sample of this file can be found in the demo download of the jdbc driver distribution. 

I also recommend adding a custom logging configuration location using the following:

-Djava.util.logging.config.file

This will allow you to add your own location for the configuration file. The resulting logging file will log even the calls made within the JDBC API which allowed us to discover an internal SQL query to retrieve the name of the tables (from the getTables() method mentioned above). This query was indeed a Statement, but a different one, thus p6spy could not possibly detect.

Hope this helps!