Groovy

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.

Subscribe
Notify of
guest

This site uses Akismet to reduce spam. Learn how your comment data is processed.

0 Comments
Inline Feedbacks
View all comments
Back to top button