NHibernate: counting database queries per web request

May 9, 2008 at 4:45 PMAndre Loker

While the upcoming NHibernate 2.0 supports statistics features out of the box, people using NHibernate 1.2 might as well be interested to determine the number of database queries that are executed on the database server.

In my specific case I was just interested in the number of DB queries per web requests, without any additional in-depth analysis. This was mostly meant as an easy detection of SELECT N+1 situations or other obvious bottlenecks. Luckily this can be quite easily done with a neat trick which is based on the fact that NHibernate uses log4net for log output. Ayende Rahien realized that NHibernate writes all executed statements to the NHibernate.SQL logger. So, to get informed over all executed database statements one would only have to implement a custom IAppender implementation and let it listen to the DEBUG messages NHibernate sends to NHibernate.SQL.

Within a few minutes I came up with this appender which counts the number of log messages - i.e. the number of SQL queries - per web request:

   1: using System.Web;
   2: using log4net.Appender;
   3: using log4net.Core;
   4:  
   5: public class CountQueriesAppender : AppenderSkeleton {
   6:     private static readonly object Key = new object();
   7:  
   8:     /// <summary>
   9:     /// Gets the number of database queries that have been executed
  10:     /// during this web request so far.
  11:     /// </summary>
  12:     /// <value>The current query count.</value>
  13:     public static int CurrentQueryCount {
  14:         get {
  15:             var val = HttpContext.Current.Items[Key];
  16:             return val == null ? 0 : (int) val;
  17:         }
  18:     }
  19:  
  20:     protected override void Append(LoggingEvent loggingEvent) {
  21:         var items = HttpContext.Current.Items;
  22:         if (items.Contains(Key)) {
  23:             // increase query count
  24:             items[Key] = 1 + (int) items[Key];
  25:         } else {
  26:             // first query, initialize with 1
  27:             items[Key] = 1;
  28:         }
  29:     }
  30: }

I only need to configure log4net to send the appropriate messages:

   1: <!-- set additivity false to prevent output to other appenders -->
   2: <logger name="NHibernate.SQL" additivity="false">
   3:   <level value="DEBUG" />
   4:   <appender-ref ref="QueryCounter" />
   5: </logger>

That's about it. Now you can access the current query count with CountQueriesAppender.CurrentQueryCount everywhere you like. For example, I render the number of executed queries in the footer of each page in debug mode. Or you could write the count back into a log on end request.

Pay attention though to the moment when you read CurrentQueryCount. Obviously it returns only queries made until that very moment. If you query the value to soon, you might miss some queries.

You can make your appender as sophisticated as you like, of course, e.g. by dissecting the provided log message (i.e. the SQL query) to distinguish between SELECT, UPDATE, INSERT and DELETE queries. Be aware that NHibernate can come up with quite some tricky queries, though, that might not be easy to parse. You might therefore want to leave it at the simple query counter as a rough estimation for now and wait for the release of NHibernate 2.0.

Last but not least: here is an example of how one could use NHibernate 2.0 statistics with MonoRail

Posted in: Databases | NHibernate | Snippets

Tags: , ,