Hibernate Debugging - Finding the origin of a Query

It's not always immediate why and in which part of the program is Hibernate generating a given SQL query, especially if we are dealing with code that we did not write ourselves.

This post will go over how to configure Hibernate query logging, and use that together with other tricks to find out why and where in the program a given query is being executed.

What does the Hibernate query log look like

Hibernate has built-in query logging that looks like this:

select /* load your.package.Employee */ this_.code, ... 
from employee this_ 
where this_.employee_id=?

TRACE 12-04-2014@16:06:02  BasicBinder - binding parameter [1] as [NUMBER] - 1000

Why can't Hibernate log the actual query ?

Notice that what is logged by Hibernate is the prepared statement sent by Hibernate to the JDBC driver plus it's parameters. The prepared statement has ? in the place of the query parameters, and the parameter values themselves are logged just bellow the prepared statement.

This is not the same as the actual query sent to the database, as there is no way for Hibernate to log the actual query. The reason for this is that Hibernate only knows about the prepared statements and the parameters that it sends to the JDBC driver, and it's the driver that will build the actual queries and then send them to the database.

In order to produce a log with the real queries, a tool like log4jdbc is needed, which will be the subject of another post.

How to find out the origin of the query

The logged query above contains a comment that allows to identify in most cases the origin of the query: if the query is due to a load by ID the comment is /* load your.entity.Name */, if it's a named query then the comment will contain the name of the query.

If it's a one to many lazy initialization the comment will contain the name of the class and the property that triggered it, etc.

In many cases the query comment created by is enough to identify the origin of the query. 

Setting up the Hibernate query log

In order to obtain a query log, the following flags need to be set in the configuration of the session factory:

<bean id= "entityManagerFactory" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean" >
  ...
  <property name="jpaProperties" >
  <props>
      <prop key="hibernate.show_sql" >true</ prop>
      <prop key="hibernate.format_sql" >true</ prop>
      <prop key="hibernate.use_sql_comments">true</prop>
  </props>
</property>

The example above is for Spring configuration of an entity manager factory. This is the meaning of the flags:

• show_sql enables query logging
• format_sql pretty prints the SQL
• use_sql_comments adds an explanatory comment

In order to log the query parameters, the following log4j or equivalent configuration is needed:

<logger name="org.hibernate.type">
    <level value="trace" />
</logger > 

If everything else fails

If the query comment added by the option use_sql_comments is not sufficient, then we can start by identifying the entity returned by the query based on the table names involved, and put a breakpoint in the constructor of the returned entity.

If the entity does not have a constructor, then we can create one and put the breakpoint in the call to super():

@Entity
public class Employee {
    public Employee() {
        super(); // put the breakpoint here
    }
    ...
}

When the breakpoint is hit, go to the IDE debug view containing the stack call of the program and go through it from top to bottom. The place where the query was made in the program will be there in the call stack.