Logging with NHibernate

I was lucky enough to find out how easy it was to start logging my NHibernate queries to a file the other day. Unfortunately it was because I was investigating a performance issue.

Your first option if you're logging whilst you're running unit tests is to just use the ShowSql method. This logs all the queries that NHibernate is running to the console. If you're using the fluent interfact for NHibernate your initiation code might look like this.

return Fluently.Configure()
    .Database(MySQLConfiguration.Standard.Dialect<MySQL5Dialect>()
    .ConnectionString("Some connection string"))
    .Mappings(m => m.FluentMappings.AddFromAssembly(GetMappingsAssembly()))
    .BuildSessionFactory();

Simply add the call to ShowSql

return Fluently.Configure()
    .Database(MySQLConfiguration.Standard.Dialect<MySQL5Dialect>()
    .ShowSql()
    .ConnectionString("Some connection string")
    .Mappings(m => m.FluentMappings.AddFromAssembly(GetMappingsAssembly()))
    .BuildSessionFactory();

You'll then see output form your unit tests in the console when you next run them.

The other option is to use log4net to log all the details that NHibernate already logs. I won't get into how to use log4net here as that's a whole separate post but you will need to add the following section to your web.config (or app.config).

<log4net debug="false">
  <appender name="NHibernateRollingFile" type="log4net.Appender.RollingFileAppender,log4net" >
    <param name="File" value="NHibernateLog.txt" />
    <param name="AppendToFile" value="false" />
    <param name="RollingStyle" value="Date" />
    <param name="DatePattern" value="yyyy.MM.dd" />
    <param name="StaticLogFileName" value="true" />
    <layout type="log4net.Layout.PatternLayout,log4net">
      <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n" />
    </layout>
  </appender>
  <logger name="NHibernate" additivity="false">
    <level value="WARN" />
    <appender-ref ref="NHibernateRollingFile" />
  </logger>
  <logger name="NHibernate.SQL" additivity="false">
    <level value="DEBUG" />
    <appender-ref ref="NHibernateRollingFile" />
  </logger>
</log4net>

You will also need to add the following line of code to tell log4net to set itself up.

log4net.Config.XmlConfigurator.Configure();

Obviously you will also need to add a reference to log4net using NuGet.

You should now get a log file at the root of your application called NHibernateLog.txt. This will contain all the queries that NHibernate has run. All we have done is tell the log messages that NHibernate is already creating where to go. The NHibernate logger section is just telling log4net to log all errors from NHibernate and the NHibernate.SQL tells it to log all SQL statements.