Debugging Hibernate Generated SQL

In this article, I will explain how to debug Hibernate’s generated SQL so that unexpected query results be traced faster either to a faulty dataset or a bug in the query.

There’s no need to present Hibernate anymore. Yet, for those who lived in a cave for the past years, let’s say that Hibernate is one of the two main ORM frameworks (the second one being TopLink) that dramatically ease database access in Java.

One of Hibernate’s main goal is to lessen the amount of SQL you write, to the point that in many cases, you won’t even write one line. However, chances are that one day, Hibernate’s fetching mechanism won’t get you the result you expected and the problems will begin in earnest. From that point and before further investigation, you should determine which is true:

• either the initial dataset is wrong
• or the generated query is
• or both if you’re really unlucky

Being able to quickly diagnose the real cause will gain you much time. In order to do this, the greatest step will be viewing the generated SQL: if you can execute it in the right query tool, you could then compare pure SQL results to Hibernate’s results and assert the true cause. There are two solutions for viewing the SQL.

Show SQL

The first solution is the simplest one. It is part of Hibernate’s configuration and is heavily documented. Just add the following line to your hibernate.cfg.xml file:

<hibernate-configuration>
  <session-factory>
...
    <property name="hibernate.show_sql">true</property>
  </session-factory>
</hibernate-configuration>

The previous snippet will likely show something like this in the log:
select this_.PER_N_ID as PER1_0_0_, this_.PER_D_BIRTH_DATE as PER2_0_0_, this_.PER_T_FIRST_NAME as PER3_0_0_, this_.PER_T_LAST_NAME as PER4_0_0_ from T_PERSON this_

Not very readable but enough to copy/paste in your favourite query tool.

The main drawback of this is that if the query has parameters, they will display as ? and won’t show their values, like in the following output:

select this_.PER_N_ID as PER1_0_0_, this_.PER_D_BIRTH_DATE as PER2_0_0_, this_.PER_T_FIRST_NAME as PER3_0_0_, this_.PER_T_LAST_NAME as PER4_0_0_ from T_PERSON this_ where (this_.PER_D_BIRTH_DATE=? and this_.PER_T_FIRST_NAME=? and this_.PER_T_LAST_NAME=?)

If they’re are too many parameters, you’re in for a world of pain and replacing each parameter with its value will take too much time.

Yet, IMHO, this simple configuration should be enabled in all environments (save production), since it can easily be turned off.

Proxy driver

The second solution is more intrusive and involves a third party product but is way more powerful. It consists of putting a proxy driver between JDBC and the real driver so that all generated SQL will be logged. It is compatible with all ORM solutions that rely on the JDBC/driver architecture.

P6Spy is a driver that does just that. Despite its age (the last release dates from 2003), it is not obsolete and server our purpose just fine. It consists of the proxy driver itself and a properties configuration file (spy.properties), that both should be present on the classpath.

In order to leverage P6Spy feature, the only thing you have to do is to tell Hibernate to use a specific driver:

<hibernate-configuration>
  <session-factory>
    <!-- Only this line changes -->
    <property name="connection.driver_class">com.p6spy.engine.spy.P6SpyDriver</property>
...
 </session-factory>
</hibernate-configuration>

This is a minimal spy.properties:

module.log=com.p6spy.engine.logging.P6LogFactory
realdriver=org.hsqldb.jdbcDriver
autoflush=true
excludecategories=debug,info,batch,result
appender=com.p6spy.engine.logging.appender.StdoutLogger

Notice the realdriver parameter so that P6Spy knows where to redirect the calls.

With just these, the above output becomes:
1270906515233|3|0|statement|select this_.PER_N_ID as PER1_0_0_, this_.PER_D_BIRTH_DATE as PER2_0_0_, this_.PER_T_FIRST_NAME as PER3_0_0_, this_.PER_T_LAST_NAME as PER4_0_0_ from T_PERSON this_ where (this_.PER_D_BIRTH_DATE=? and this_.PER_T_FIRST_NAME=? and this_.PER_T_LAST_NAME=?)|select this_.PER_N_ID as PER1_0_0_, this_.PER_D_BIRTH_DATE as PER2_0_0_, this_.PER_T_FIRST_NAME as PER3_0_0_, this_.PER_T_LAST_NAME as PER4_0_0_ from T_PERSON this_ where (this_.PER_D_BIRTH_DATE=’2010-04-10′ and this_.PER_T_FIRST_NAME=’Johnny’ and this_.PER_T_LAST_NAME=’Be Good’)

Of course, the configuration can go further. For example, P6Spy knows how to redirect the logs to a file, or to Log4J (it currently misses a SLF4J adapter but anyone could code one  easily).

If you need to use P6Spy in an application server, the configuration should be done on the application server itself, at the datasource level. In that case, every single use of this datasource will be traced, be it from Hibernate, TopLink, iBatis or plain old JDBC.

In Tomcat, for example, put spy.properties in common/classes and update the datasource configuration to use P6Spy driver.

The source code for this article can be found here.

To go further:

• P6Spy official site
• Log4jdbc, a Google Code contender that aims to offer the same features

From http://blog.frankel.ch/debugging-hibernate-generated-sql