在单元测试中计算NHibernate执行的查询次数

8
在我们的一些代码的单元/集成测试中,我们希望检查我们的代码是否正确使用了第二级缓存。基于Ayende在此处提供的代码:

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

我为此编写了一个简单的类:

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;
      }
    }
}

使用意图:

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

但是它总是返回查询计数为0。没有sql语句被记录。

然而,如果我使用NHibernate Profiler并在我的测试用例中调用它:

NHibernateProfiler.Intialize()

NHProf采用类似的方法来捕获NHibernate的日志输出,以便通过log4net等进行分析,然后我的QueryCounter开始工作。

看起来我在代码中漏掉了一些内容,以使log4net正确配置以记录nhibernate sql ... 有人可以指点我还需要做什么才能从Nhibernate获取sql日志输出吗?

附加信息:

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>

展示SQL语句:true

根据jfneis的回复,我编写了一个更简单的类,只使用NHibernate的工厂统计信息:

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};
  }
}

一旦启用统计功能,它就可以很好地工作。


在你的NHibernate配置中,你是否将show_sql设置为true了?请问你能否也发布一下你的log4net.config文件? - mhanney
是的,我已经尝试过将show_sql设置为true和false。虽然我认为show_sql不使用log4net,只是将SQL语句转储到stdout?我现在已经在初始问题中包含了我的log4net配置。NHibernateProfiler.Initialize()导致我的类起作用,这表明我可能缺少一些编程log4net配置。 - Bittercoder
Bittercoder,我现在不在我的开发机上,所以无法发布代码,但你是否尝试过使用Statistics来实现?我也曾遇到过这种测试L2和统计数据的问题,对于我的场景已经足够了。12个小时后回到办公室,如果需要的话我会发布完整的答案。希望这能暂时帮到你。 - jfneis
你在应用程序启动时是否调用了log4net.Config.XmlConfigurator.Configure()函数? - mhanney
<appender-ref ref="ConsoleAppender" /> 应该改为 <appender-ref ref="console" />。如果只是这个问题的话,我会感到惊讶,不过还是想提一下。 - mhanney
1个回答

13

判断缓存是否命中或者是否执行查询还有另一种更简单的方法(在我看来):使用统计数据。

首先,你需要在NH配置文件中启用统计信息:

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

之后,您可以随时向会话工厂询问情况。您已经谈到了L2缓存测试,因此您可以这样做:

        // 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);

但是,如果你真正想要的是查询计数,那么“统计信息”界面中有许多其他选项可供选择:

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

好的,就这些。希望这对您有所帮助,就像它帮助了我一样。

祝好,

Filipe


我查看了统计数据,没有找到任何查询统计信息 - 但我正在查看ISessionStatistics、ISessionFactory.Statistics (IStatistics)。我会尝试一下 :) - Bittercoder
实现了使用统计学的简单类 - 效果非常棒 - 感谢José的帮助! - Bittercoder
3
QueryExecutionCount并不能准确显示SELECT语句执行的次数?我想改善N+1的情况,但单个会话的List调用会创建第一个select,然后又创建27个。但QueryExecutionCount仍然是1。我认为你需要使用PrepareStatementCount。 - jrwren

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接