I spent the first half of February giving a Hibernate training course to a client with offices in Dallas (USA) and Krakow (Poland). The delegates in both locations made me very welcome, so thanks very much to all for some enjoyable sessions.

This was a brand new training course, so as always it was interesting to see how the material went across. Version 2 of the course will contain some updated content addressing questions raised in the course, and much of this will also end up in the next edition of Beginning Hibernate.

The candidates from both locations had plenty of sharp questions, so this post addresses one of them that is of broader interest - how to get the information on named and ordinal parameters used in Hibernate queries.

Hibernate already has some conspicuous configuration properties that allow you to log the generated SQL (and HQL) to standard output. To recap on these, they are:

• hibernate.show_sql - Display the SQL statements
• hibernate.format_sql - Format the SQL statements to be more readable
• hibernate.use_sql_comments - Display a comment indicating what operation caused the SQL statement to be generated

Here's the output when I enable all three of these options during the login phase of my current work in progress:

Hibernate:
    /* named HQL query findUserByEmail */ select
        user0_.id as id0_,
        user0_.accountNonExpired as accountN2_0_,
        user0_.accountNonLocked as accountN3_0_,
        user0_.contact_id as contact9_0_,
        user0_.created as created0_,
        user0_.credentialsNonExpired as credenti5_0_,
        user0_.email as email0_,
        user0_.enabled as enabled0_,
        user0_.encodedPassword as encodedP8_0_
    from
        LolaUser user0_
    where
        user0_.email=?

So far so good, but there are a couple of problems here. Firstly I would prefer this logged information to be in the logs not sent to the console. That's easy enough to amend, however: enable DEBUG level logging on org.hibernate.SQL. The appropriate log4j configuration entry is log4j.logger.org.hibernate.SQL=DEBUG. Disable the show_sql option in the Hibernate properties and the logs will now contain the (nearly identical) entry as follows:

DEBUG SQL -
    /* named HQL query findUserByEmail */ select
        user0_.id as id0_,
        user0_.accountNonExpired as accountN2_0_,
        user0_.accountNonLocked as accountN3_0_,
        user0_.contact_id as contact9_0_,
        user0_.created as created0_,
        user0_.credentialsNonExpired as credenti5_0_,
        user0_.email as email0_,
        user0_.enabled as enabled0_,
        user0_.encodedPassword as encodedP8_0_
    from
        LolaUser user0_
    where
        user0_.email=?

Note that the other configuration options (format_sql and use_sql_comments) apply equally to console output and log output. However, there is a performance cost to enabling the formatting. The additional clarity is worth the cost in development environments but you will almost certainly want to disable this in production environments as the content is otherwise unchanged.

Now for the second problem - what value did we set for that parameter? The original HQL query looked like this: from User where email = :email but that doesn't tell me much except that the named parameter (":email") probably corresponds to the ordinal parameter ("?") used in the prepared statement.

I could manually log this when I set the named parameter, but that sounds too much like hard work. Let's turn on some additional logging instead:

log4j.logger.org.hibernate.engine.QueryParameters=DEBUG
log4j.logger.org.hibernate.engine.query.HQLQueryPlan=DEBUG

The first one enables tracing of the named parameter, the second is necessary to enable the invocation of the named parameter logging from the query planner (and is useful anyway). Both are necessary to get this information, which then looks like this:

DEBUG HQLQueryPlan - find: from User where email = :email
DEBUG QueryParameters - named parameters: {email=dave@paperstack.com}
DEBUG SQL -
    /* named HQL query findUserByEmail */ select
        user0_.id as id0_,
        user0_.accountNonExpired as accountN2_0_,
        user0_.accountNonLocked as accountN3_0_,
        user0_.contact_id as contact9_0_,
        user0_.created as created0_,
        user0_.credentialsNonExpired as credenti5_0_,
        user0_.email as email0_,
        user0_.enabled as enabled0_,
        user0_.encodedPassword as encodedP8_0_
    from
        LolaUser user0_
    where
        user0_.email=?

So far so (fairly) good, but there is still a trace of ambiguity. I'm assuming that the named parameter used in the HQL and the ordinal parameter used in the prepared statement are equivalent, but what if they're not? And if there were multiple parameters this would be a significant problem. I've definitely got my named parameters muddled up in the past, so I would really like this information to be made explicit. To see this mapping, apply the following logging option:

log4j.logger.org.hibernate.type=DEBUG

This enables the trace-level logging of parameter types as they are applied to prepared statements, and you will now get the final part of the picture:

DEBUG HQLQueryPlan - find: from User where email = :email
DEBUG QueryParameters - named parameters: {email=dave@paperstack.com}
DEBUG SQL -
    /* named HQL query findUserByEmail */ select
        user0_.id as id0_,
        user0_.accountNonExpired as accountN2_0_,
        user0_.accountNonLocked as accountN3_0_,
        user0_.contact_id as contact9_0_,
        user0_.created as created0_,
        user0_.credentialsNonExpired as credenti5_0_,
        user0_.email as email0_,
        user0_.enabled as enabled0_,
        user0_.encodedPassword as encodedP8_0_
    from
        LolaUser user0_
    where
        user0_.email=?
DEBUG StringType - binding 'dave@paperstack.com' to parameter: 1
DEBUG LongType - returning '1' as column: id0_
DEBUG BooleanType - returning 'true' as column: accountN2_0_
DEBUG BooleanType - returning 'true' as column: accountN3_0_
DEBUG LongType - returning null as column: contact9_0_
DEBUG CalendarType - returning '2008-02-25 17:08:36' as column: created0_
DEBUG BooleanType - returning 'true' as column: credenti5_0_
DEBUG StringType - returning 'dave@paperstack.com' as column: email0_
DEBUG BooleanType - returning 'true' as column: enabled0_
DEBUG StringType - returning 'd3f4429e4a47863c62e4bb723f205c26' as column: encodedP8_0_   

Note that we get information on the returned values as well as the transmitted ones, which can also be useful for debugging. Of course you could just turn on DEBUG level logging for the org.hibernate.engine package, or even org.hibernate itself, but the torrent of information you'll get at that point is definitely a lot more than you'd want to see in a production environment, inflicts snow-blindness even in test environments, and has some real performance costs. That said the return values logged with debug logging on org.hibernate.type are probably excessive too, so you will have to exercise some judgment in applying these options. Sometimes manually logging the named parameters as you execute queries may be the best approach after all.

In practice these are the log4j configuration entries that I normally use:

log4j.logger.org.hibernate.engine.QueryParameters=DEBUG
log4j.logger.org.hibernate.engine.query.HQLQueryPlan=DEBUG
log4j.logger.org.hibernate.SQL=DEBUG
# Enable type debugging only when necessary to diagnose problems
#log4j.logger.org.hibernate.type=DEBUG

And these are the Hibernate cfg entries that I normally use:

<property name="hibernate.show_sql">false</property>
<property name="hibernate.format_sql">false</property>
<property name="hibernate.use_sql_comments">true</property>

Although all of these examples are given using the log4j configuration options, Hibernate is actually using the Apache Commons logging API, and generating this information at the trace level, so adjust accordingly if you're using some other base logging framework.