Hibernate: Write SQL to a specific logfile (without additional framework)

This post will show a simple setup logging Hibernate’s SQL statements to a single file, including all the parameters, using only log4j and (of course) Hibernate.

SQL in Hibernate

For the purpose of seeing the magic behind a object-relational mapper (e.g. for debugging), it’s always useful to have a look at the actual SQL queries that are created.

Especially, if you are working (or have to work) with something as useful as Hibernate’s Criteria API.

In Hibernate, the simplest way is to set the parameter hibernate.show_sql to true and Hibernate will log all SQL statements to system out.

Straight after setting this option, two things come to mind:

• Even small applications can generate tons of SQL statements on your log and
• the SQL statements contain only question marks instead of the actual paramaters, which leaves them only partly useful.

I can’t count the number of SystemOut.log files I saw that were so flooded with Hibernate’s SQL drivel that the important log statements were nowhere to be found.

Using additional Frameworks

In order to solve these issues, the best approaches might be to intercept the SQL statements on JDBC level and then logging them. This can be achieved using a framework like p6spy or log4jdbc. Those frameworks will log the complete SQL statements including the actual parameter values instead of question marks to a file.

However, those frameworks require a lot of effort on configuration. In some cases they can’t be used at all, e.g. in enterprise software – log4jdbc doesn’t even support maven (as of log4jdbc 4.1.2).

Using only Hibernate (and log4j)

A by far simpler alternative is to swiftly set up your logging framework (which should already be part of your application) to log the SQL statements, the values of the parameters and the values returned by the database to a separate file.

A configuration for log4j might look as follows:

log4.properties

log4j.rootLogger=INFO, File, Console

log4j.logger.my.application=DEBUG, File

log4j.logger.org.hibernate=WARN, File, Console
log4j.additivity.org.hibernate.SQL=false
log4j.logger.org.hibernate.SQL=DEBUG, FileSql
log4j.additivity.org.hibernate.SQL=false
log4j.logger.org.hibernate.type=TRACE, FileSql
log4j.additivity.org.hibernate.type=false

log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=%d{ISO8601} %-5p %c{1} %l - %m%n

log4j.appender.File=org.apache.log4j.DailyRollingFileAppender
log4j.appender.File.datePattern='.'yyyy-MM-dd
log4j.appender.File.file=logs/myApplication.log
log4j.appender.File.layout=org.apache.log4j.PatternLayout
log4j.appender.File.layout.ConversionPattern=%d{ISO8601} %-5p %c{1} %l - %m%n

log4j.appender.FileSql=org.apache.log4j.DailyRollingFileAppender
log4j.appender.FileSql.datePattern='.'yyyy-MM-dd
log4j.appender.FileSql.file=logs/myApplication_sql.log
log4j.appender.FileSql.layout=org.apache.log4j.PatternLayout
log4j.appender.FileSql.layout.ConversionPattern=%d{ISO8601} %-5p %c{1} - %m%

This results in all SQL statements being logged to myApplication_sql.log whereas all other application-related messages (including warnings issued by Hibernate) are written to myApplication.log.

The important part is the additivity parameter, which avoids the log messages being propagated to the parent logger. That is, the SQL statements will not flood your system out.

This solution has only one drawback compared to the additional frameworks solution: It still contains the question marks. However, the org.hibernate.type logger writes additional log statements that contain the values.

Note: Setting the logger org.hibernate.SQL to DEBUG seems to be equivalent to setting the parameter hibernate.show_sql to true.

In addition I’d always recommend to set the hibernate.format_sql parameter to true in order to make the SQL statements easier to read.

The result might look something like this

2013-04-16 21:18:47,684 DEBUG SQL -
    select
        table0_.id as id0_1_
    from
        app table0_
    where
        table0_.val=?
2013-04-16 21:18:47,684 TRACE BasicBinder - binding parameter [1] as [BIGINT] - 95
2013-04-16 21:18:47,684 TRACE BasicExtractor - Found [1] as column [id0_1_]

Conclusion

To conclude, using log4j can be set up in no time and contains all the necessary information for debugging (including the values returned by the database), whereas a dedicated JDBC logging framework requires more configuration effort but puts out the SQL statements more neatly.

Links

Once more, I found most of the information aggregate in this article on stackoverflow: here and there. Thanks guys!