4

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

dave clements
  • 1,505
  • 2
  • 13
  • 28
  • How long does it take with ADO.NET? – Michael Maddox Feb 16 '10 at 13:41
  • What is the main bottleneck when you profile the code with a profiler like ants or dottrace? – Paco Feb 16 '10 at 14:51
  • Using ADO.NET it takes a fraction of the time that NHibernate does. I've not got any profiling software installed at the moment, so i'm just going to get that sorted and see what it says – dave clements Feb 16 '10 at 15:03
  • Ants is showing the whole process as only taking 160ms, which is a tenth of what my tests and NH Profiler are telling me. I've tried re-running with NH Profiler detached, in case that was the problem, and that's not made any difference either – dave clements Feb 16 '10 at 17:17
  • Measuring different times makes it confusing. How long does it take when you use a System.Diagnostics.Stopwatch to time the actual execution of the code that calls the method using NHibernate and the database? I hope that can give you the "real" time. – Paco Feb 16 '10 at 22:47
  • Using the stopwatch gives me the same result - approximately 1800ms – dave clements Feb 17 '10 at 10:22

2 Answers2

8

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

dave clements
  • 1,505
  • 2
  • 13
  • 28
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.

No Refunds No Returns
  • 8,092
  • 4
  • 32
  • 43
  • I've just run the exact query that NHibernate generates using a data reader, and the total execution time is just over 1ms, so, unfortunately, it doesn't appear to be a network latency issue – dave clements Feb 16 '10 at 14:56
  • that's my point ... now try reading your data and extracting each column into your "row container" whatever that is. You'll probably see a slow down. – No Refunds No Returns Feb 17 '10 at 00:29
  • I've just re-run this to check, and creating the connection, running the query (i'm doing this against the simple count to make it as easy as possible) and reading the data out takes just over a millisecond. – dave clements Feb 17 '10 at 10:30