NHibernate taking a long time to run query

Question

This is being done using Fluent NHibernate

I've got a NHibernate lookup that is retrieving data from one table. If i take the generated sql and run it through query analyzer, it takes ~18ms to run.

Using NHProfiler, i'm getting the duration of this query as ~1800ms - 100 times longer than sql !

Query duration
 - Database only:1800ms
 - Total: 1806ms

The object that is being populated contains a child class, but this child is being loaded from the NHibernate 2nd level cache

The data that is being returned is paged (50 per query) although as far as i can tell, this shouldn't make any difference

I've also got a count running, and again, this is taking ~4ms in query analyzer and ~1800ms according to NHProfiler.

Is NH Profiler displaying the query execution time, or the complete time to retrieve, map the classes and construct the object graph? And if it's the former - why's it taking so much longer than running the query directly?

EDIT: Just found this post by Ayende about the Query Duration value given in NH Profiler: http://ayende.com/Blog/archive/2009/06/28/nh-prof-query-duration.aspx - so it is definitely the query of the database that is taking a long time

Answer 1

generally these problems resolve to the network between you and your data base. QA usually connects directly to the data base and all it has to send is the raw data back where its formatted. Your app is probably converting your result set into a data set or similar construct. To prove this, change a bit of code (not your entire data layer) to use a SQL Data Reader to read your data. Just read all of the records without trying to parse out all of the columns and save the data. It will likely perform as fast as your network will let it.

Answer 2

Finally managed to track down the problem.

The primary key for the object is a varchar in the database. NHibernate was converting the value to an nvarchar when it ran the query. Unfortunately this wasn't obvious when looking at the generated sql in NH Profiler. The slowdown was caused by sql converting the nvarchar back to a varchar

I've specified the mapping to use a custom type

map.Id(x => x.Id).CustomType("AnsiString");

and the problem is solved

Cheers for all the help people :)