Kash Farooq's software development blog

.NET Developer

Posts Tagged ‘log4net’

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.

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

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.

Posted in .NET | Tagged: , | 2 Comments »