Thursday, June 17, 2010

Grails, p6spy and Sql Profiler

There are several ways to have Grails log SQL statements that Hibernate is sending to the database under the covers of GORM.  The first is the loggingSql flag in DataSource.groovy:


This will show you the prepared statement that Hibernate is generating, like this:

SELECT AS id6_0_,
        this_.version AS version6_0_,
        this_.authority AS authority6_0_,
        this_.description AS descript4_6_0_
        role this_

This is a good first step – but what if I want to see the parameter that is being sent as well?  You could turn logging for the org.hibernate.type package to TRACE level:

//in Config.groovy
log4j = {
    trace  'org.hibernate.type'

YIKES! That gets REALLY noisy, really fast:

    select as id6_0_,
        this_.version as version6_0_,
        this_.authority as authority6_0_,
        this_.description as descript4_6_0_
        role this_
TRACE type.StringType  - binding 'ROLE_USER' to parameter: 1
TRACE type.LongType  - returning '1' as column: id6_0_
TRACE type.LongType  - returning '1' as column: version6_0_
TRACE type.StringType  - returning 'ROLE_USER' as column: authority6_0_
TRACE type.StringType  - returning 'Default user role' as column: descript4_6_0_

Besides, what I really want is the ability to copy and paste a query, with the parameters bound, directly into a SQL editor to execute the query and see the results myself. Enter the p6spy plugin for Grails:

grails install-plugin p6spy

Swap the driver in your DataSource.groovy file from your driver to the p6spy driver (the plugin will automatically add this, you just need to comment it in):

environments {
  development {
    dataSource {
      //driverClassName = "org.hsqldb.jdbcDriver"
      driverClassName = "com.p6spy.engine.spy.P6SpyDriver"

Fire up your Grails application – p6spy will create a spy.log file in your application directory and log a pipe delimited line – the last column has the actual SQL being executed, with the parameters!

select as id2_0_, this_.version as version2_0_, this_.authority as authority2_0_, this_.description as descript4_2_0_ from role this_ where this_.authority='ROLE_USER'

This is a great start, and most people stop here. But sometimes there are so many queries being executed that it’s difficult to wade through spy.log to find the one you’re looking for. Thanks to a tip from the excellent Grails In Action book that was recently released – SQL Profiler can help!

Download SQL Profiler ( and add these lines to grails-app/conf/

Add the appender to the logger definition:


Finally, make sure the Log4j Appender is enabled:

#specifies the appender to use for logging

Then, in the directory in which you downloaded the SQL Profiler jar, launch the GUI with this line:

java -jar sqlprofiler.jar

Now, p6spy will log SQL to the SQL Profiler GUI! You can use it to profile SQL statements, but you can also use the ‘Logger’ tab to filter the log. I click the little trash can icon in the upper left to clear the log, run a test in the application, then filter the results using the filter fields available. For instance, if I only want to see queries related to the ‘ROLE’ table, just put the word ‘role’ in the Filter message text box, and you’ll only see queries related to that table. It’s a great way to get straight at a particular SQL query when you’re drowning in tons and tons of SQL messages.

1 comment:

  1. This is really useful information. I'm surprised there are no comments on this 2 year old article. Thanks for the share!