How to log Hibernate SQL statements including binding parameter values with Logback / SLF4J

When working with Hibernate as a Java ORM Framework,  SQL becomes kind of a black box for developers. This is fine in most cases and is exactly the purpose of such frameworks, but the time comes when you want to know the truth…. the raw SQL statements.
I realized that it is kind of hard to really get to the SQL statements, especially if you also want to know the statement AND the binding parameters. For those who don’t know the binding parameters are the actual values for the question marks in the queries. 

The output you will get from this short tutorial is something like this:

2013-08-30 18:01:15,083 | update stepprovider set created_at=?, lastupdated_at=?, version=?, bundlelocation=?, category_id=?, customer_id=?, description=?, icon_file_id=?, name=?, shareStatus=?, spversion=?, status=?, title=?, type=?, num_used=? where id=? 
2013-08-30 18:01:15,084 | binding parameter [1] as [TIMESTAMP] - 2012-07-11 09:57:32.0 
2013-08-30 18:01:15,085 | binding parameter [2] as [TIMESTAMP] - Fri Aug 30 18:01:15 CEST 2013 
2013-08-30 18:01:15,086 | binding parameter [3] as [INTEGER] -  
2013-08-30 18:01:15,086 | binding parameter [4] as [VARCHAR] - com.mypackage.foo 
2013-08-30 18:01:15,087 | binding parameter [5] as [VARCHAR] -  
2013-08-30 18:01:15,087 | binding parameter [6] as [VARCHAR] -  
2013-08-30 18:01:15,087 | binding parameter [7] as [VARCHAR] - TODO 
2013-08-30 18:01:15,087 | binding parameter [8] as [VARCHAR] -  
2013-08-30 18:01:15,088 | binding parameter [9] as [VARCHAR] - MatchingStep@com.mypackage.foo
2013-08-30 18:01:15,088 | binding parameter [10] as [VARCHAR] - PRIVATE 
2013-08-30 18:01:15,088 | binding parameter [11] as [VARCHAR] - 1.0 
2013-08-30 18:01:15,088 | binding parameter [12] as [VARCHAR] - 32 
2013-08-30 18:01:15,088 | binding parameter [13] as [VARCHAR] - MatchingStep 
2013-08-30 18:01:15,089 | binding parameter [14] as [VARCHAR] -  
2013-08-30 18:01:15,089 | binding parameter [15] as [INTEGER] - 0 
2013-08-30 18:01:15,089 | binding parameter [16] as [VARCHAR] - 053c2e65-5d51-4c09-85f3-2281a1024f64

If you are using Logback as your SLF4J implementation the following logback-test.xml or logback-main.xml snippet is needed to get a nice output like this:

<appender name="SQLROLLINGFILE">
 <File>/tmp/sql.log</File>	
<rollingPolicy> 
<FileNamePattern>logFile.%d{yyyy-MM-dd}.log</FileNamePattern>	
</rollingPolicy><layout>	 
<Pattern>%-4date | %msg %n</Pattern>	
</layout>
</appender>
<logger name="org.hibernate.SQL" additivity="false" >	<level value="DEBUG" />	<appender-ref ref="SQLROLLINGFILE" /></logger>
<logger name="org.hibernate.type" additivity="false" >	<level value="TRACE" />	<appender-ref ref="SQLROLLINGFILE" /></logger>

This will create a file under the path /tmp/sql.log (if you are under Windows replace ‘/tmp/’ with e.g. ‘c:/somefolder/’).
Warning: This file can become very large in a short number of seconds depending on how much SQL your application is doing in the background. If you have lots of background jobs running or a large number of queries this file can reach a few gigabyte in a few minutes easily. So watch your disk space ;)

Dieser Beitrag wurde unter Software-Development abgelegt und mit , , , verschlagwortet. Setze ein Lesezeichen auf den Permalink.