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
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 :)