Know what happens on your database

Although I believe that an ORM should take care of the persistence, you as a developer NEED to know what happens on your database.  You need to know what SQL - statements get fired.  NHibernate uses Log4Net for this, with a simple configuration setting you make NHibernate log all statements that make the trip to the database.  In the hibernate-configuration you can set the "show_sql" property to true.  You then need to specify the Nhibernate logger (be sure to name this "NHibernate.SQL" and link it to an appender.  The following config section simply does that:

 1 <log4net>
 2     <appender name="NHibernateSQLLog" type="log4net.Appender.RollingFileAppender">
 3         <file value="nhibernate_sql_statements.txt"/>
 4         <appendToFile value="true"/>
 5         <rollingStyle value="Size"/>
 6         <maxSizeRollBackups value="10"/>
 7         <maximumFileSize value="1000KB"/>
 8         <staticLogFileName value="true"/>
 9         <layout type="log4net.Layout.PatternLayout">
10             <conversionPattern value="%d{HH:mm:ss.fff} [%t] %-5p %c - %m%n"/>
11         </layout>
12     </appender>
13     <logger name="NHibernate.SQL" additivity="false">
14         <level value="DEBUG"/>
15         <appender-ref ref="NHibernateSQLLog"/>
16     </logger>
17 </log4net>

As already mentioned in a previous post we had to be very persuasive in order to use NHibernate.  One of the questions our DBA guys had was "what was going on on their database, can we see what queries and statements get executed?".  The above gives us all information, however it is not very useful for them as they have to go through tons of duplicate statements.  Fortunately Log4Net is very extensible, you can easily build your Appender and filter out the information you do not want to log.  The easiest solution is to extend the appender you would normally use, (for example the RollingFileAppender) and override FilterEvent method.  You can then return false for every loggingEvent that you do not want written out. 

 1 private static List<String> statements = new List<string();
 2 
 3 
 4 protected override bool FilterEvent(log4net.Core.LoggingEvent loggingEvent)
 5 {
 6     string message = loggingEvent.RenderedMessage;
 7     int index = loggingEvent.RenderedMessage.IndexOf(";");
 8     if (index != -1) 
 9     {
10          message = loggingEvent.RenderedMessage.Substring(0, index);
11     }
12             
13     if (statements.Contains(message))
14     {
15          return false;
16     }
17 
18     statements.Add(message);
19 
20     return base.FilterEvent(loggingEvent);
21 }

In this example I build a list of all statements that have already been logged.  First we need to filter out the parameters, because otherwise no statement would be unique.  The loggingEvent contains a RenderedMessage that consist of two parts.  First the actual statement containing wildcards or named parameters.  Then the character ';' and lastly the mapping of the parameters.  We only need the part before the ';' because any statement can be called multiple times with different parameters.  Once we have the actual query statement we try to find this in our list and return false if it has already been logged.  The result is that our logfile now only contain unique statements.  The parameters included are those from the first time this statement was logged (Since the RenderedMessage is read-only we cannot remove these).