Kash Farooq's software development blog

.NET Developer

Improve the performance of NHibernate by getting your log4net settings right

Posted by Kash Farooq on December 5, 2008

We had a performance problem.
Hydrating 200 objects and their associated non-lazy collections was taking 50-60 seconds, in which time the client would time out.
The fix was trivial, but it took a while to find it. We were checking web servers, databases, event logs, code, etc, etc.

Finally we installed JetBrain’s dotTrace on the web server and grabbed a snapshot of the w3wp.exe process. dotTrace is easy to use and the snapshot easy to interpret. We found where all the time was being spent – in NHibernate’s debug methods!
The penny dropped and I checked the web.config.

    <priority value="Debug" />
  <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
     <someMoreSettings />
     <filter type="log4net.Filter.LoggerMatchFilter">
     <LoggerToMatch value="NHibernate" />
       <AcceptOnMatch value="False" />

Basically, these settings meant that NHibernate was logging everything and log4net was filtering it out with the AcceptOnMatch=false configuration item.

Changing the priority level to “Info” reduced the query time to 3.5 seconds!

It was a stupid mistake but took a long time to track down. We should have installed dotTrace earlier.

2 Responses to “Improve the performance of NHibernate by getting your log4net settings right”

  1. khadden said

    Good god man! We’ve been rolling back code in TFS for 6 hours now. Finally narrowed it down to a new call to XmlConfigurator.Configure( ) which was put in just before loading our WCF services.

    Couldn’t figure out why it would slow stuff down. But your suggestion solved the problem.


  2. Al Priest said

    I prefer to specify the exact logger name so that you can leave your root logger at the DEBUG level:

Sorry, the comment form is closed at this time.

%d bloggers like this: