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

Hi I dont think you are looking at the right place. You shouldnt be looking at the database duration etc. You cannot do much with the execution once it gets to the dB lvl.

Instead what you should be concentrating on is how many queries do you send to the db. Can you minimise them somehow by avoiding redundant calls or caching some query. Are you retrieving only the properties that concern you or are you loading up an entire object into memory and then working on it.

Also what platform are you working on, I might be able to suggest better tools for you to use to identify bottle neck in your app.

Hope that helps.

Answer 2

I don't know it for a fact but I always assumed that the Total duration adds all the NHibernate overhead of constructing the SQL query, and upon data retrieval constructing the entities with the raw data.

Perhaps the construction process with your entities is very slow? Do you have some extensive processing in your entities constructors? any IO operations, logging, additional DB access, network usage...

Good luck

Answer 3

The first result is the time it took to execute and retrieve the result from the DB. The second result is the time it takes NHibernate to load the corresponding entities in memory.

Im working in a project right now which utilizes a very large entity (almost 100 columns/fields). If i try to load a couple of thousand it will also take a few seconds. However, the sql-query will return the list of entity-ids in a few milliseconds. But to actually load these ids into the corresponding entities, generates extra overhead if your entites are large or complex object (see the post above).

Do you get any alerts for the generated queries? The column right next to Duration in NHibernate Profiler.

Best regards,
Mattias

Answer 4

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.