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:
covers this topic primarily by discussing the 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.
0 comments:
Post a Comment