Piraguablog » Blog Archive » Grails, p6spy and Sql Profiler

Grails, p6spy and Sql Profiler

June 17, 2009 – 10:46 pm

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:

loggingSql=true

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

SELECT
        this_.id AS id6_0_,
        this_.version AS version6_0_,
        this_.authority AS authority6_0_,
        this_.description AS descript4_6_0_
    FROM
        role this_
    WHERE
        this_.authority=?

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:

Hibernate:
    select
        this_.id as id6_0_,
        this_.version as version6_0_,
        this_.authority as authority6_0_,
        this_.description as descript4_6_0_
    from
        role this_
    where
        this_.authority=?
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 this_.id 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 (http://sourceforge.net/projects/sqlprofiler) and add these lines to grails-app/conf/spy.properties:

log4j.appender.SQLPROFILER_CLIENT=org.apache.log4j.net.SocketAppender
log4j.appender.SQLPROFILER_CLIENT.RemoteHost=localhost
log4j.appender.SQLPROFILER_CLIENT.Port=4445
log4j.appender.SQLPROFILER_CLIENT.LocationInfo=true

Add the appender to the logger definition:

log4j.logger.p6spy=INFO,STDOUT,SQLPROFILER_CLIENT

Finally, make sure the Log4j Appender is enabled:

#specifies the appender to use for logging
appender=com.p6spy.engine.logging.appender.Log4jLogger
#appender=com.p6spy.engine.logging.appender.StdoutLogger
#appender=com.p6spy.engine.logging.appender.FileLogger

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.

6 Responses to “Grails, p6spy and Sql Profiler”
That’s awesome Mike, thanks for the tips. I’d previously used p6spy at your suggestion and it’s been very helpful. Adding sqlprofiler to the toolset makes it even easier to see what’s going on.

By Ted Naleid on Jun 18, 2009
Very interesting and will be helpful in my stuff. Thanks for the post.

By pupkin on Jun 22, 2009
I see “Connected to p6spy” in the UI, but I dont get any output in the UI.

By Sakuraba on Jun 24, 2009
This looks really useful! But, I also didn’t see anything much ni the UI except “Connected to p6spy” … looking at teh console for sqlprofiler I see that the data flowing to sqlprofiler isn’t being parsed right:

[Thread-4] DEBUG org.jahia.sqlprofiler.gui.LoggingReceiver – Starting to get data
Exception in thread “Thread-2″ java.lang.NumberFormatException: For input string: “08:39:51″
at java.lang.NumberFormatException.forInputString(NumberFormatException.java:48)
at java.lang.Long.parseLong(Long.java:412)
at java.lang.Long.parseLong(Long.java:461)
at org.jahia.sqlprofiler.QueryEntry.parseP6Encoding(QueryEntry.java:134)
at org.jahia.sqlprofiler.QueryEntry.(QueryEntry.java:35)
at org.jahia.sqlprofiler.gui.ProfileStatementTableModel.processP6Event(ProfileStatementTableModel.java:81)
at org.jahia.sqlprofiler.gui.LoggerTableModel$Processor.run(LoggerTableModel.java:137)
at java.lang.Thread.run(Thread.java:619)

Did you do anything to sqlprofiler to get it to parse the inbound string properly?

By Wayne Stidolph on Aug 27, 2009
I’m trying to get this working in 1.2 and having no luck with the logging output.

The P6Spy shows green and i get the 3 init messages, driverManager; registeredDriver and reloadProperties.

I have logSql=true in my datasource and am seeing the HSQl dumping to console as i use the app. No SQL statements of further logging appears in P6SPy app os spy.log (they never have)

I followed you examples exactly as above – here is my spy.properties

realdriver=com.mysql.jdbc.Driver
log4j.appender.SQLPROFILER_CLIENT=org.apache.log4j.net.SocketAppender
log4j.appender.SQLPROFILER_CLIENT.RemoteHost=localhost
log4j.appender.SQLPROFILER_CLIENT.Port=4445
log4j.appender.SQLPROFILER_CLIENT.LocationInfo=true
log4j.logger.p6spy=DEBUG,STDOUT,SQLPROFILER_CLIENT

appender=com.p6spy.engine.logging.appender.Log4jLogger

Is there anything that needs to be changed in the log4j config of the app? This is what I have

log4j = {
error ‘grails.app’, ’stdout’, ‘file’
root {
error()
}
additivity = true
}

I also have Grails in Action and nothing in there is helping me resolve this.

When running the app with ‘-Dlog4j.debug=true’ i get the following output

log4j: Trying to find [log4j.xml] using context classloader java.net.URLClassLoader@10f0625.
log4j: Trying to find [log4j.xml] using org.codehaus.groovy.grails.cli.support.GrailsRootLoader@fd13b5 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader java.net.URLClassLoader@10f0625.
log4j: Using URL [jar:file:/home/jerome/grails/dist/grails-scripts-1.2-M2.jar!/log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL jar:file:/home/jerome/grails/dist/grails-scripts-1.2-M2.jar!/log4j.properties
log4j: Parsing for [root] with value=[error, NULL].
log4j: Level token is [error].
log4j: Category root set to ERROR
log4j: Parsing appender named “NULL”.
log4j: Parsed “NULL” options.
log4j: Finished configuring.
No authentication for svn repo at ywRepository …
log4j: setFile called: stacktrace.log, true
log4j: setFile ended
The plugin is disabled therefore nothing needs to be done here.
Running Grails application..
8-Oct-2009 2:18:30 PM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
8-Oct-2009 2:18:30 PM org.apache.catalina.core.StandardService start
INFO: Starting service Tomcat
8-Oct-2009 2:18:30 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0-snapshot
8-Oct-2009 2:18:30 PM org.apache.catalina.startup.ContextConfig defaultWebConfig
INFO: No default web.xml
8-Oct-2009 2:18:31 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring root WebApplicationContext
log4j: Could not find root logger information. Is this OK?
log4j: Parsing for [p6spy] with value=[DEBUG,STDOUT,SQLPROFILER_CLIENT].
log4j: Level token is [DEBUG].
log4j: Category p6spy set to DEBUG
log4j: Parsing appender named “STDOUT”.
log4j:ERROR Could not find value for key log4j.appender.STDOUT
log4j:ERROR Could not instantiate appender named “STDOUT”.
log4j: Parsing appender named “SQLPROFILER_CLIENT”.
log4j: Setting property [port] to [4445].
log4j: Setting property [locationInfo] to [true].
log4j: Setting property [remoteHost] to [localhost].
log4j: Parsed “SQLPROFILER_CLIENT” options.
log4j: Handling log4j.additivity.p6spy=[null]
log4j: Finished configuring.
Server running. Browse to http://localhost:8080/imt-grails-webapp

By j pimmel on Oct 8, 2009

1 Trackback(s)
Sep 30, 2009: Ted Naleid » Batch Import Performance with Grails and MySQL

Sorry, comments for this entry are closed at this time.

Grails, p6spy and Sql Profiler

6 Responses to “Grails, p6spy and Sql Profiler”

1 Trackback(s)

Recent Posts

Archives