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] - asdand
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.
