Logging in grails 1.3.7

Logging capabilities haven improved a lot in grails 2.0, but my main project is still running on grails 1.3.7 and somehow I never managed to get any of the profiling plugins to work. I was suspecting that my application made a lot of repetitive and unnecessary requests to the SQL database so I needed a way to figure out what was happening between hibernate and the JDBC connection. Hibernate comes with its own logging but unfortunately it doesn't tell you anything about the response time of the database. So I was digging google and found this very promising approach on http://piraguaconsulting.blogspot.com/2010/06/grails-p6spy-and-sql-profiler.html, where p6spy basically replaces your database driver with a shadow version that logs all communication. Unfortunately this didn't work for my project. I use a C3P0 connection pool and the shadow driver of p6spy can't handle that (at least not as far as I could see). A pity since it seemed to be a good idea especially in combination with http://sourceforge.net/projects/sqlprofiler/ which combines the logging with a nice GUI.

However, this approach gave me a basic idea of what I was looking for and googling deeper I found http://code.google.com/p/log4jdbc/ which in contrast to p6spy is actively developed. Hooking it up with grails is super easy. You add the lib file to your project, exchange the database driver in your dataSource config with

net.sf.log4jdbc.DriverSpy

and adjust your database url:

Before:
jdbc:sqlserver://localhost:1433;databaseName=olabdb;

After:
jdbc:log4jdbc:sqlserver://localhost:1433;databaseName=olabdb;

Simple as that. The shadow driver of log4jdbc seems to recognize the most common SQL drivers and includes them without any effort from my side.

In order to turn logging on you add 'jdbc.sqltiming' to you log4j config in Config.groovy, e.g.
Log4j config is also explained here: http://grails.org/doc/latest/guide/conf.html#logging

Now it already works and gives you a nice and informative output including the parameters that are actually part of the SQL query. This helps a lot to learn how your domain model is reflected in the SQL world.


2012-03-08 10:58:10,515 [http-8080-5] INFO  jdbc.sqltiming  - select genes0_.recombinant_genes_id as recombin1_0_, genes0_.gene_id as gene2_0_ from gtRecombinant_gtGene
genes0_ where genes0_.recombinant_genes_id=977


My lesson was that inheritance is actually a bad thing since it causes multiple joins for each query that you do on a child class. Another thing I don't like is how hard it is to read the statements since all column names are referred to by a different name. A little more digging and I found this really nice post:

http://softdevbuilttolast.wordpress.com/2010/02/22/hibernate-sql-logging-log4jdbc-haciendo-log-de-sql-con-hibernate-log4jdbc/

It teaches you how to configure log4jdbc efficiently and to tailor it towards your needs. In my case I added a few starting parameters to my VM:

-Dlog4jdbc.debug.stack.prefix=org.openlab

This one allows you to specify your applications main package, which in turn allows log4jdbc to see where your own code begins. As a result it tells you which line of code caused the SQL query. SUPER NICE. Note that it only seems to work on log level 'all'.

Among hundreds of queries you want to see the "bad guys" that just take too long. You can set time thresholds for log.warn and log.error via

-Dlog4jdbc.sqltiming.warn.threshold=200
-Dlog4jdbc.sqltiming.error.threshold=1000