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.