NHibernate SQL query slow

问题:

I am using LINQ to NH to get a bunch of data on app startup. I specifically added ToList() to force immediate query execution:

Group group = GetGroup();
Log.Info("started");
var list = Session.Linq<Data>()
    .Where(p => p.Group.Id == group.Id)
    .OrderByDescending(p => p.Stamp.Counter) /* Stamp is composite mapping */
    .Select(p => new
    {
        Counter = p.Stamp.Counter,
        Status = p.Status,
    })
    .Take(4000)
    .ToList();
Log.Info("done");

Checking the DEBUG log for NHibernate.SQL logger gives the following SQL, as expected (and this same query pops out in SQL Profiler, when I start monitoring):

SELECT top 4000 this_.Counter as y0_, this_.Status as y1_
FROM [Data] this_ 
LEFT OUTER JOIN [Group] group1_ ON this_.Group_id=group1_.Id
WHERE group1_.Id = @p0 
ORDER BY this_.Counter desc; @p0 = 1

The problem is that this query takes 2 minutes to complete when invoked from my app, compared to 0.5s when executed in SSMS! Actually, while the app is waiting for the query to complete, I can execute it in SSMS and get results instantly.

Where do you think this difference comes from?

回答1:

Sinces there is not much information about your application, I only can guess.

Performance problems with NH typically occur caused by flushing the cache. The cache is flushed before each query. When there are lots of entities in the session, it may take quite a lot of time. Try the following:

Log.Info("Flushing");
Session.Flush();
Session.FlushMode = FlushMode.Never;

Log.Info("Query");
var list = Session.Linq<Data>()
    //...
Log.Info("Done");
// for production code, this belongs into a finally block
Session.FlushMode = FlushMode.Auto; 

If it actually is a flushing problem, you need to flush manually on certain points in the transaction. Be careful when turning off auto flush. It may cause ugly side effects. It is very specific to your transaction and I can't say you how to implement it the right way. You could also use a StatelessSession, but for me it never worked (it has some limits). You may also clear the session, which also requires that you exactly know what you are doing.

If it is no flushing problem, it gets difficult to track. Use Profiler to see if it actually takes the time in the SQL server query. It may even be a caching problem on SQL server. In this case it takes minutes the first time you execute the query, but only seconds the second time. Creating proper indexes may help. Here I stop guessing...

回答2:

My assumption that there is some interceptors that slow down objects materialization or eager loading(i.e. N+1 problem).

I've done some test and even 30 000 objects cannot slow down getting list of objects(from local machine 500ms to get list of 30000 objects, from remote db - 4 seconds).

回答3:

There are a couple of possible reasons:

• You're loading at least 4000 objects into memory, hydrating them and also NHibernate must keep control of every loaded object in the Session and 1st level cache
• I haven't seen your mappings, but it is very likely that there is some sort of eager loading at some point, wich will also spam other queries and loading of other objects and so on

These come from the top of my head, there could me more. Also check if NHibernate's log level isn't set to DEBUG, it is VERY detailed and can consume LOTS of resources.

回答4:

One nice point out of a project today:

I searched about one week for the reason why my nHibernate query (multicriteria using futures to eager load some collections) took 11 seconds (duration in MSSQL profiler) and about 2 seconds if I execute exactly the same combined query in SSMS.

The solution was: I had some logging activated to run Ayendes profiler. The NHProf dlls where missing, but: Some GetRows methods in nHibernate trigger log calls during hydration. And the difference was: 9 seconds!

I just commented out the log4net configure call and the delay is almost gone.

I had about 14.000 instances plus 60.000 HasMany collection entries. Hydration takes now 0.6 seconds because the SQL statement takes 2 seconds (this is another optimization story).

And: I think the hydration duration together with the query execution duration is shown in the SQL profiler "duration" column.

Another story 2 weeks ago was: The execution plans in SQL profiler were different from the ones delivered when executing the query in SSMS. The reason for this was, that I used OLEDB provider in nHibernate. I switched to ADO connections and the execution plan was the same. I found this when looking at some "protocol version" column in MS SQL profiler.

There are so many reasons for performance pitfalls beyond n+1 :)

Best wishes! Michael