«    »

Hibernate and Logging

Hibernate tries to hide the details of dealing with relational databases, but it is at best a leaky abstraction. At its most basic level, Hibernate is a framework that issues SQL commands to the database. Sometimes it does not do what you would expect or want (more on that in future articles). Therefore it is very useful at times to monitor or review the SQL being produced by Hibernate. The book Java Persistence with Hibernate covers this topic primarily by discussing the show.sql hibernate configuration property which writes generated SQL to the console. I have found this far too limiting: I instead want the SQL logged in my application's log (i.e. as produced by log4j) to receive all the advantages that a central logging system can provide. This can be accomplished by turning on DEBUG logging for the logging context org.hibernate.SQL. If you are using log4j, add the following line to your log4j.properties file:

log4j.logger.org.hibernate.SQL=DEBUG

One limitation of this SQL logging is that it reports the SQL statement but not the values of the parameters. Since Hibernate almost always uses prepared statements with parameters, this is often an annoying limitation. Fortunately, Hibernate does allow the logging of parameter values: turn on DEBUG logging for the logging context org.hibernate.type. Unfortunately, this results in very verbose logs since each parameter value for each query is a separate log entry. A sample log entry for a single insert statement is shown below.

07 Feb 2008 13:30:52,596 DEBUG insert into example.customer (CATEGORY, 
CREATE_USER_ID, CREATE_TIMESTAMP, UPDATE_USER_ID, UPDATE_TIMESTAMP, OID) 
values (?, ?, ?, ?, ?, ?) - org.hibernate.SQL [main] [44513 ms]

07 Feb 2008 13:30:52,596 DEBUG binding 'S' to parameter: 1 - 
hibernate.type.StringType [main] [44513 ms]

07 Feb 2008 13:30:52,596 DEBUG binding 'junit test' to parameter: 2 - 
hibernate.type.StringType [main] [44513 ms]

07 Feb 2008 13:30:52,596 DEBUG binding '2008-02-07 13:30:52' to parameter: 3 - 
hibernate.type.DbTimestampType [main] [44513 ms]

07 Feb 2008 13:30:52,596 DEBUG binding '2008-02-07 13:30:52' to parameter: 4 - 
hibernate.type.TimestampType [main] [44513 ms]

07 Feb 2008 13:30:52,596 DEBUG binding 'junit test' to parameter: 5 - 
hibernate.type.StringType [main] [44513 ms]

07 Feb 2008 13:30:52,596 DEBUG binding '2691102' to parameter: 6 - 
hibernate.type.LongType [main] [44513 ms]

I much prefer the way that Spring JDBC logs SQL statements – both the SQL and the list of parameter values are logged as a single statement. If you know how to do this in Hibernate, I would appreciate hearing from you.

Hibernate uses Apache's commons-logging to abstract the actual logging mechanism: typically either log4j or Java logging (introduced in Java 1.4). I always use log4j myself, and normaly including the log4j jar file in the classpath is sufficient to have commons-logging use log4j. When running code in an application server, however, this is not always the case. I have had issues with both WebSphere and WebLogic application servers configuring commons-logging for some other behavior and having that setting 'leak' into my application. As a result, instead of having log messages from Hibernate appear in the application log along with the rest of the log statements produced directly with the log4j API, the Hibernate log messages appear elsewhere. In WebSphere 6.1, I had them going to the console (standard out). The simplest solution is to add a configuration file named commons-logging.properties to the root of your application's classpath with the following content that instructs commons-logging to use log4j for logging:

org.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger

This article is one of a series on Hibernate Tips & Tricks.

If you find this article helpful, please make a donation.

7 Comments on “Hibernate and Logging”

  1. Peter Kelley says:

    I think that that log implementation class should be org.apache.commons.logging.impl.Log4JLogger (upper case J)

  2. Thanks Peter! I made the fix.

  3. Sasha says:

    Thank you Basil for a good tip.

    I’ve got a slightly different problem where Hibernate 3.2.6.ga does not log “debug” messages when running in Tomcat 5.5 (which in its turn runs in JBoss 4.0.3). I’ve tried creating commons-logging.properties but it did not log debug messages either.

    However, when I run the same code in a standalone environment, I’ve got all debug messages coming from hibernate.

    All suggestions would be greatly appreciated.

  4. Paul G says:

    If you use sl4j you get none of the websphere problems. Sl4j provides a bridge so it will work with jcl and then you can use log4j or the new replacement logback.

  5. Paul G says:

    Jcl “smart” classloader scanning cause no end of problems in servers. I would really suggest looking at sl4j which may help with everyones logging in server issues.

  6. Bill says:

    In your sample log snippet, each entry ends with “[44513 ms]“. What does that represent? If that is how long the query took to run (although I’d hope it didn’t take 44 seconds), or you know how to log query duration, please post.

  7. @Bill, the last portion of each entry represents the elapsed duration (in milliseconds) since the application started (more accurately, I believe, when Log4J was initialized.) I use this both as an uptime statistic and as a way to compare elapsed time between two log entries.

    This does NOT represent query duration, and I’m not aware of an easy way to log this. One option that comes to mind is to use aspects to weave in before/after method advice on either Hibernate query methods directly or on methods in your Data Access Objects (DAOs) to measure and log the performance.

«    »