Viewing the SQL generated by NHibernate

There are at least a couple of ways to view the SQL generated by NHibernate. The easiest way is probably to use the hibernate.show_sql configuration property to dump it all to Console.Out:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section
       name="nhibernate"
       type="System.Configuration.NameValueSectionHandler, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
    />
  </configSections>  
  <nhibernate>
    <add
      key="hibernate.connection.provider"
      value="NHibernate.Connection.DriverConnectionProvider"
    />
    ...
    <add key="hibernate.show_sql" value="true" />
  </nhibernate>
</configuration>

Another way is to configure log4net. NHibernate logs a wealth of information, but you can restrict it to just the generated SQL by doing the following:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section
       name="nhibernate"
       type="System.Configuration.NameValueSectionHandler, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
    />
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net"/>
  </configSections>  
  <nhibernate>
    ...
  </nhibernate>  
  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date - %message%newline"/>
      </layout>
    </appender>
    <!-- NHibernate.SQL logs all generated SQL (see update below) -->
    <logger name="NHibernate.SQL" additivity="false">
      <level value="DEBUG" />
      <appender-ref ref="ConsoleAppender" />
    </logger>
    <!-- 
      NHibernate.Loader.Loader logs diagnostic stuff and SELECTs. 
      You can use either logger, or both, depending on you needs.
    -->
    <logger name="NHibernate.Loader.Loader" additivity="false">
      <level value="INFO" />
      <appender-ref ref="ConsoleAppender" />
    </logger>
  </log4net>
</configuration>

Update: Kenneth Xu helpfully pointed out in the comments that NHibernate.SQL is better for this than NHibernate.Loader.Loader (which this post originally used), providing more information on both the queries and the updates generated by NHibernate. Dave Perry also pointed out that NHibernate.SQL logs at DEBUG level rather than INFO. Thanks Kenneth and Dave!

This configuration means that anything logged from the NHibernate.SQL class will go through the logger with the matching name. This class happens to log NHibernate-generated SQL as DEBUG messages. You can also use NHibernate.Loader.Loader, which logs various diagnostics and SELECTs.

To get this log4net configuration to work, I had to make sure the following code was executed once in the relevant AppDomain: log4net.Config.XmlConfigurator.Configure();. In my case, I chucked it in the test fixture setup. Calling it multiple times doesn’t seem to break anything, but you really only need to call it once to pickup your configuration.

Unlike the hibernate.show_sql option, this does not show the values of the parameters passed for substitution in each SQL statement.

Viewing logs in NUnit

NUnit has a Log tab that lists log4net logging information, as well as displaying Console.Out and Console.Error. If you go to the Tools menu –> Options –>Text Output, you can get NUnit to “Display TestCase Labels” for each test. Combined with the logging options above, you can then get a nice view of the SQL used for each of your tests.

NUnit displaying NHibernate generated SQL

More information

I found this post from Mike Nichols a very helpful reference on NHibernate logging. There is also some official documentation on the subject.

Comments