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>
key="hibernate.connection.provider"
value="NHibernate.Connection.DriverConnectionProvider"
/>
...
</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) -->
<level value="DEBUG" />
<appender-ref ref="ConsoleAppender" />
</logger>
<!--
You can use either logger, or both, depending on you needs.
-->
<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.

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