NHibernate Profiler - large discrepancy between database duration and total duration?

Question

I have an application that makes extensive use of NHibernate. I've started using the NHibernate Profiler to identify possible performance issues. My question is related to the Query Durations statistic.

The stat is broken down in Database Duration and Total Duration. From what I've read, the numbers should be very close. However, I'm seeing relatively large disparities and I'm trying to figure out the source of these. Here's some data

Any idea on where I can start to fix these issues?

Answer 1

Is your application using log4net? If so, you should check your log4net configuration and turn down the amount of data that you're logging from NHibernate.

An example from a project that I'm working on right now: For a query returning 60 rows / objects, logging all NHibernate log messages at DEBUG level to a file increases the total NHProf reported duration from 8ms to around 8000ms!

Example configuration to limit NHibernate output:

<root>
    <level value="ALL" />
    <appender-ref ref="console" />
    <appender-ref ref="trace" />
</root>

<logger name="NHibernate">
    <level value="WARN" />
</logger>

IF this doesn't resolve your problem, perhaps you could use a performance profiling tool like dotTrace or ANTS Profiler to identify potential bottlenecks in your code. This will give you a clear indication of which methods within your / NHibernate's code are taking a lot of time.