hibernar.org
A friendly forum for Hibernate users
<< Back to Articles

Logging SQL generated by Hibernate

Hibernate translates our queries and object operations into SQL statements.

This shows how to configure your log file (assumed to be log4j, in xml format), in order to log the SQL statements in a separate file.

First of all you should know that, for very simple SQL visualization needs, there is a configuration property called hibernate.show_sql (which can be set to true or false). It determines whether or not Hibernate will log its generated SQL to the console.
However, this property is not very useful, because it logs at the DEBUG level only (this means, all our application has to be logging everything up to DEBUG level, which usually produces too much information). Besides, this property causes Hibernate to log to the console only, which generally doesn't help much.


A better solution is to send all generated SQL statements to a file. This can be easily achieved through our log4J configuration file.
The following log4j configuration file creates 2 files: "normal.log" and "sql.log".
The file "normal.log" will contain our application's normal logging, at whatever level we wish to set it (normally INFO).
The file "sql.log" will contain exclusively the SQL generated by Hibernate.
Additionally, we will output the content of both files to the console.
Example log4j.xml file: 
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

   <appender name="appenderConsole" class="org.apache.log4j.ConsoleAppender">
       <layout class="org.apache.log4j.SimpleLayout"/>
   </appender>

       <appender name="appenderNormalFile" class="org.apache.log4j.RollingFileAppender">
           <param name="File" value="/logs/normal.log"/>
           <param name="Append" value="true"/>
           <param name="MaxFileSize" value="500KB"/>
           <param name="MaxBackupIndex" value="1"/>
           <layout class="org.apache.log4j.PatternLayout">
                <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
           </layout>
       </appender>

       <appender name="appenderSQLFile" class="org.apache.log4j.RollingFileAppender">
           <param name="File" value="/logs/sql.log"/>
           <param name="Append" value="true"/>
           <param name="MaxFileSize" value="500KB"/>
           <param name="MaxBackupIndex" value="1"/>
           <layout class="org.apache.log4j.PatternLayout">
               <param name="ConversionPattern" value="%d %m%n"/>
           </layout>
       </appender>

   <category name="org.hibernate.SQL" additivity="false">
      <priority value="debug" />
      <appender-ref ref="appenderConsole" />
      <appender-ref ref="appenderSQLFile" />
   </category>


   <root>
      <priority value="info" />
      <appender-ref ref="appenderConsole" />
      <appender-ref ref="appenderNormalFile" />
   </root>

</log4j:configuration>
This log4j configuration file has generated 3 "appenders": one for the console, another for the "normal" another for the normal log file, and a third for the SQL-only log file.
SQL queries are generated by classes inside the org.hibernate.SQL package, so, what this configuration file does, is to create a "category" with that package, and direct every logging output produced inside that category to our special "appender" for SQL code: appenderSQLFile.
Also notice that our generated SQL code will go to our SQL log file (located at /logs/sql.log), regardless of the general log level of the application (in this case, INFO).


You might have notice that the log produced using this configuration file does not give you the values of the parameters.
(When the generated SQL has parameters, it simply logs a ? placeholder, but it doesn't tell you the name or value of the parameters).

This can be partially solved by adding the following category to the previous log4j.xml file: 
   <category name="org.hibernate.type" additivity="false">
       <priority value="debug" />
   <appender-ref ref="appenderConsole" />
   <appender-ref ref="appenderFileSQL" />
   </category>
What this extra category does, is to watch the org.hibernate.type, which deals with parameter names and values.

The extra parameter logging once we add this category will look something like this: 
 2008-07-28 09:57:12,081 DEBUG org.hibernate.type.IntegerType - binding '3' to parameter: 2
 2008-09-18 09:57:12,082 DEBUG org.hibernate.type.StringType - binding '' to parameter: 3
 2008-09-18 09:57:12,082 DEBUG org.hibernate.type.StringType - binding '' to parameter: 4
 2008-09-18 09:57:12,082 DEBUG org.hibernate.type.LongType - binding '511' to parameter: 5
 2008-09-18 09:57:12,082 DEBUG org.hibernate.type.LongType - binding '512' to parameter: 6
 2008-09-18 09:57:12,082 DEBUG org.hibernate.type.LongType - binding null to parameter: 7
 2008-09-18 09:57:12,082 DEBUG org.hibernate.type.LongType - binding '180030' to parameter: 8
Unfortunately, watching org.hibernate.type will also output the values that have been associated to each column name on each row, which will usually result in too much information being logged.
But you might still want to keep that extra category in your log configuration file, and comment it out when not needed.