Logging Hibernate SQL

There are two well-known ways to log Hibernate SQL in Grails; one is to add logSql = true in DataSource.groovy (either in the top-level block for all environments or per-environment)

 
 

 
 

 
 

dataSource {
   dbCreate = ...
   url = ...
   ...
   logSql = true
}

and the other is to use a Log4j logging configuration:

log4j = {
   ...
   debug 'org.hibernate.SQL'
}

The problem with logSql is that it’s too simple – it just dumps the SQL to stdout and there is no option to see the values that are being set for the positional ? parameters. The logging approach is far more configurable since you can log to the console if you want but you can configure logging to a file, to a file just for these messages, or any destination of your choice by using an Appender.

But the logging approach is problematic too – by enabling a second Log4j category

log4j = {
   ...
   debug 'org.hibernate.SQL'
   trace 'org.hibernate.type'
}

we can see variable values, but you see them both for PreparedStatement sets and for ResultSet gets, and the gets can result in massive log files full of useless statements. This works because the “Type” classes that Hibernate uses to store and load Java class values to database columns (for example LongType, StringType, etc.) are in the org.hibernate.type package and extend (indirectly) org.hibernate.type.NullableType which does the logging in its nullSafeSet and nullSafeGet methods.

So if you have a GORM domain class

class Person {
   String name
}

and you save an instance

new Person(name: 'me').save()

you’ll see output like this:

DEBUG hibernate.SQL  - insert into person (id, version, name) values (null, ?, ?)
TRACE type.LongType  - binding '0' to parameter: 1
TRACE type.StringType  - binding 'me' to parameter: 2
DEBUG hibernate.SQL  - call identity()

When you later run a query to get one or more instances

def allPeople = Person.list()

you’ll see output like this

DEBUG hibernate.SQL  - select this_.id as id0_0_, this_.version as version0_0_, this_.name as name0_0_ from person this_
TRACE type.LongType  - returning '1' as column: id0_0_
TRACE type.LongType  - returning '0' as column: version0_0_
TRACE type.StringType  - returning 'me' as column: name0_0_

This isn’t bad for one instance but if there were multiple results then you’d have a block for each result containing a line for each column.

I was talking about this yesterday at my Hibernate talk at SpringOne 2GX and realized that it should be possible to create a custom Appender that inspects log statements for these classes and ignores the statements resulting from ResultSet gets. To my surprise it turns out that everything has changed in Grails 2.x because we upgraded from Hibernate 3.3 to 3.6 and this problem has already been addressed in Hibernate.

The output above is actually from a 1.3.9 project that I created after I got unexpected output in a 2.1.1 application. Here’s what I saw in 2.1.1:

DEBUG hibernate.SQL  - 
    /* insert Person
        */ insert 
        into
            person
            (id, version, name) 
        values
            (null, ?, ?)

TRACE sql.BasicBinder  - binding parameter [1] as [BIGINT] - 0

TRACE sql.BasicBinder  - binding parameter [2] as [VARCHAR] - asd

and

DEBUG hibernate.SQL  -
    /* load Author */ select
        author0_.id as id1_0_,
        author0_.version as version1_0_,
        author0_.name as name1_0_
    from
        author author0_
    where
        author0_.id=?

TRACE sql.BasicBinder  - binding parameter [1] as [BIGINT] - 1

TRACE sql.BasicExtractor  - found [0] as column [version1_0_]

TRACE sql.BasicExtractor  - found [asd] as column [name1_0_]

So now instead of doing all of the logging from the types’ base class, it’s been reworked to delegate to org.hibernate.type.descriptor.sql.BasicBinder and org.hibernate.type.descriptor.sql.BasicExtractor. This is great because now we can change the Log4j configuration to

log4j = {
   ...
   debug 'org.hibernate.SQL'
   trace 'org.hibernate.type.descriptor.sql.BasicBinder'
}

and have our cake and eat it too; the SQL is logged to a configurable Log4j destination and only the PreparedStatement sets are logged.

Note that the SQL looks different in the second examples not because of a change in Grails or Hibernate but because I always enable SQL formatting (with format_sql) and comments (with use_sql_comments) in test apps so when I do enable logging it ends up being more readable, and I forgot to do that for the 1.3 app:

hibernate {
   cache.use_second_level_cache = true
   cache.use_query_cache = false
   cache.region.factory_class = 'net.sf.ehcache.hibernate.EhCacheRegionFactory'
   format_sql = true
   use_sql_comments = true
}

 

Reference: Logging Hibernate SQL from our JCG partner Burt Beckwith at the An Army of Solipsists blog.

Do you want to know how to develop your skillset to become a Java Rockstar?

Subscribe to our newsletter to start Rocking right now!

To get you started we give you two of our best selling eBooks for FREE!

JPA Mini Book

Learn how to leverage the power of JPA in order to create robust and flexible Java applications. With this Mini Book, you will get introduced to JPA and smoothly transition to more advanced concepts.

JVM Troubleshooting Guide

The Java virtual machine is really the foundation of any Java EE platform. Learn how to master it with this advanced guide!

Given email address is already subscribed, thank you!
Oops. Something went wrong. Please try again later.
Please provide a valid email address.
Thank you, your sign-up request was successful! Please check your e-mail inbox.
Please complete the CAPTCHA.
Please fill in the required fields.

Leave a Reply


nine − 8 =



Java Code Geeks and all content copyright © 2010-2014, Exelixis Media Ltd | Terms of Use | Privacy Policy | Contact
All trademarks and registered trademarks appearing on Java Code Geeks are the property of their respective owners.
Java is a trademark or registered trademark of Oracle Corporation in the United States and other countries.
Java Code Geeks is not connected to Oracle Corporation and is not sponsored by Oracle Corporation.
Do you want to know how to develop your skillset and become a ...
Java Rockstar?

Subscribe to our newsletter to start Rocking right now!

To get you started we give you two of our best selling eBooks for FREE!

Get ready to Rock!
You can download the complementary eBooks using the links below:
Close