SQL Zone is brought to you in partnership with:

Nicolas Frankel is an IT consultant with 10 years experience in Java / JEE environments. He likes his job so much he writes technical articles on his blog and reviews technical books in his spare time. He also tries to find other geeks like him in universities, as a part-time lecturer. Nicolas is a DZone MVB and is not an employee of DZone and has posted 218 posts at DZone. You can read more from them at their website. View Full User Profile

Debugging Hibernate Generated SQL

04.13.2010
| 20238 views |
  • submit to reddit

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

Published at DZone with permission of Nicolas Frankel, author and DZone MVB.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Comments

Andy Jefferson replied on Tue, 2010/04/13 - 3:46am

Hibernate is one of the two ORM frameworks (the second one being TopLink) that dramatically ease database access in Java

Just for the record, there are actually plenty of persistence frameworks that do this type of thing, not just 2 : OpenJPA, Apache OJB, DataNucleus, EBean to name but 4.

With DataNucleus to debug the SQL you simply look at the log, where the SQL is logged in its own log category, and actually includes the parameter values in the SQL so none of this messing about with P6Spy and such.

Nicolas Frankel replied on Tue, 2010/04/13 - 4:51am

Hi Andy,

Granted they are more. Yet, from my experience, I've only seen Hibernate (mostly) and TopLink (rarely). Sometimes, they are accessed through JPA...

It would be interesting to have statistics about each use but it isn't far fetched to approximate to these two major actors.

Thanks for your interest.

Erin Garlock replied on Tue, 2010/04/13 - 7:11am

Digging into Google trends here are the results:

hibernate 1.00
toplink 0.02
openjpa 0.01
datanucleus 0
apache ojb 0
ebean 0
  

Andy Jefferson replied on Tue, 2010/04/13 - 7:59am in response to: Nicolas Frankel

Hi Nicolas, my comment is simply related to the fact that your use of English ("one of the two") denied the existence of these other options. And no, no matter what usage you decide is actual (my experience is of all 4 primary open source persistence tools - DataNucleus has a different target than other RDBMS-centric tools) that doesn't give you the right to approximate to anything. Simply providing adequate wording such as "Hibernate is the most widely used ORM framework aimed at easing RDBMS access for Java" would suffice. That way you are correct, and don't offend anybody, and people can focus on the positive things you're trying to get across in the article. Thx

Nicolas Frankel replied on Tue, 2010/04/13 - 8:21am in response to: Andy Jefferson

You're right! I'm editing the post, thanks for your advice.

Sam Lewis replied on Tue, 2010/04/13 - 10:36am

Before installing p6spy I would add these lines to my log4j.properties file:

log4j.logger.org.hibernate.SQL=DEBUG
log4j.logger.org.hibernate.type=TRACE

The first is equivalent to hibernate.show_sql=true, the second prints the bound parameters among other things.

Robin Bygrave replied on Wed, 2010/04/14 - 4:50pm in response to: Erin Garlock

wrt Google trends ...

 You may want to use "eclipselink" rather than "toplink".

 

In terms of Ebean, for those that don't know it uses JPA annotations for mapping BUT it uses a session-less architecture (aka no Hibernate Session and could also be described as having "automatic management of the persistence context").

So Ebean exists just to make your life even simplier. In regards logging sql... it has transaction logs where sql/dml, bind variables and a 'summary' are logged together with a transaction id.

Ok, this is starting to sound like a shameless plug for Ebean :) ... but it's at zero so it needs the marketing :)

 

Cheers, Rob.

Robin Bygrave replied on Wed, 2010/04/14 - 5:13pm in response to: Robin Bygrave

Maybe interesting for some ...

"Origin Point" ... in the transaction logs.

In terms of building object graphs there is the 'original/origin' query ... and then secondary queries invoked by lazy loading (or to optimise the query for multiple *ToMany relationships 'query joins').

Ebean can identify the 'origin' point of a query and all subsequent queries (lazy loading queries, query joins) that relate to that 'origin'.

Ebean uses this as part of it's automatic query tuning ("Autofetch") ... but we have just started logging the 'orgin' into the transaction logs ... so you can easily identify a lazy loading query and relate it back to it's origin (even if you don't use "Autofetch"). This is helpful for manual tuning of queries.

Apologies for the shameless plug again... but there is more to ORM transaction logs than just sql and bind values and transaction ids.

 

Cheers, Rob.

 

 

Nicolas Frankel replied on Fri, 2010/04/16 - 5:12am in response to: Robin Bygrave

I don't know nothing about Ebean and I won't argue about the product but the log produced (the theme of this article) is not copy/pastable into a SQL Query product (Toad or what have you):

trans[1004], 08:51:39.587, delete from e_basicver where id=? and last_update=?
trans[1004], 08:51:39.587, Binding Delete [e_basicver] where[id=1, lastUpdate=2010-03-01 08:51:39.515, ]   

P6Spy logging fits the previous requirement, EBean logging does not.

 

Robin Bygrave replied on Fri, 2010/04/16 - 6:02am in response to: Nicolas Frankel

Yup - fair enough.

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.