Count number of queries executed by NHibernate in a unit test

Question

In some unit/integration tests of the code we wish to check that correct usage of the second level cache is being employed by our code.

Based on the code presented by Ayende here:

http://ayende.com/Blog/archive/2006/09/07/MeasuringNHibernatesQueriesPerPage.aspx

I wrote a simple class for doing just that:

public class QueryCounter : IDisposable
{
    CountToContextItemsAppender _appender;

    public int QueryCount
    {
      get { return _appender.Count; }
    }

    public void Dispose()
    {
      var logger = (Logger) LogManager.GetLogger("NHibernate.SQL").Logger;
      logger.RemoveAppender(_appender);
    }

    public static QueryCounter Start()
    {
      var logger = (Logger) LogManager.GetLogger("NHibernate.SQL").Logger;

      lock (logger)
      {
        foreach (IAppender existingAppender in logger.Appenders)
        {
          if (existingAppender is CountToContextItemsAppender)
          {
            var countAppender = (CountToContextItemsAppender) existingAppender;

            countAppender.Reset();

            return new QueryCounter {_appender = (CountToContextItemsAppender) existingAppender};
          }
        }

        var newAppender = new CountToContextItemsAppender();
        logger.AddAppender(newAppender);
        logger.Level = Level.Debug;
        logger.Additivity = false;

        return new QueryCounter {_appender = newAppender};
      }
    }

    public class CountToContextItemsAppender : IAppender
    {
      int _count;

      public int Count
      {
        get { return _count; }
      }

      public void Close()
      {
      }

      public void DoAppend(LoggingEvent loggingEvent)
      {
        if (string.Empty.Equals(loggingEvent.MessageObject)) return;
        _count++;
      }

      public string Name { get; set; }

      public void Reset()
      {
        _count = 0;
      }
    }
}

With intended usage:

using (var counter = QueryCounter.Start())
{
  // ... do something 
  Assert.Equal(1, counter.QueryCount); // check the query count matches our expectations
}

But it always returns 0 for Query count. No sql statements are being logged.

However if I make use of Nhibernate Profiler and invoke this in my test case:

NHibernateProfiler.Intialize()

Where NHProf uses a similar approach to capture logging output from NHibernate for analysis via log4net etc. then my QueryCounter starts working.

It looks like I'm missing something in my code to get log4net configured correctly for logging nhibernate sql ... does anyone have any pointers on what else I need to do to get sql logging output from Nhibernate?

Additional info:

Logging.config:

<log4net>

  <appender name="trace" type="log4net.Appender.TraceAppender, log4net">
    <layout type="log4net.Layout.PatternLayout,log4net">
      <param name="ConversionPattern" value="%d [%t] %-5p %c [%x] &amp;lt;%P{user}&amp;gt; - %m%n" />
    </layout>
  </appender>

  <appender name="console" type="log4net.Appender.ConsoleAppender, log4net">
    <layout type="log4net.Layout.PatternLayout,log4net">
      <param name="ConversionPattern" value="%d [%t] %-5p %c [%x] &amp;lt;%P{user}&amp;gt; - %m%n" />
    </layout>
  </appender>

  <appender name="debug" type="log4net.Appender.DebugAppender, log4net">
    <layout type="log4net.Layout.PatternLayout,log4net">
      <param name="ConversionPattern" value="%d [%t] %-5p %c [%x] &amp;lt;%P{user}&amp;gt; - %m%n" />
    </layout>
  </appender>

  <logger name="NHibernate.SQL" additivity="false">
    <level value="DEBUG" />
    <appender-ref ref="ConsoleAppender" />
  </logger>

  <root>
    <priority value="DEBUG" />
    <appender-ref ref="trace" />
    <appender-ref ref="console" />
    <appender-ref ref="debug" />
  </root>

</log4net>

show_sql: true

Based on jfneis response, I wrote a far simpler class which just uses NHibernate's factory statistics:

public class QueryCounter
{
  long _startCount;

  QueryCounter()
  {
  }

  public int QueryCount
  {
    get { return (int) (UnitOfWork.CurrentSession.SessionFactory.Statistics.QueryExecutionCount - _startCount); }
  }

  public static QueryCounter Start()
  {
    return new QueryCounter {_startCount = UnitOfWork.CurrentSession.SessionFactory.Statistics.QueryExecutionCount};
  }
}

Which works just fine once statistics is enabled.

Answer 1

In your nhibernate configuration have you set show_sql to true?

Please can you also post your log4net.config?

Answer 2

There's another (simpler, IMO) way to assert if cache is being hit or if queries are being executed: using Statistics.

First of all, you have to enable statistics in your NH config file:

 <property name="generate_statistics">true</property>

After that, you can ask your session factory whenever you want how things are going. You've talked about L2 cache testing, so you could have something like that:

        // act
        MappedEntity retrievedEntity = session.FindById(entity.Id);
        long preCacheCount = sessionFactory.Statistics.SecondLevelCacheHitCount;
        retrievedEntity = session.FindById(entity.Id);
        long postCacheCount = sessionFactory.Statistics.SecondLevelCacheHitCount;
        // assert
        Assert.AreEqual(preCacheCount + 1, postCacheCount);

But, if what you really want is the query count, there are plenty other options in the Statistics interface:

        sessionFactory.Statistics.QueryExecutionCount;
        sessionFactory.Statistics.TransactionCount;

Well, that's it. Hope this helps you as helped me.

Regards,

Filipe