12

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?

Improve this question
5
  • don't know the answer but this is a very interesting finding. Commented Jul 28, 2011 at 13:38
  • Is there any possibility that GetGroup() is slow? Commented Jul 28, 2011 at 14:19
  • @AlfeG, no, the query string is written to the log immediately after the "started" message, and then it hangs for a couple of minutes. Commented Jul 28, 2011 at 15:18
  • can you please try this: execute the sql query directly and see how much time it takes.. Session.CreateSqlQuery() and update the question Commented Jul 29, 2011 at 17:20
  • @user350374: good idea (but it will have to wait until Monday) :) Commented Jul 29, 2011 at 20:26

4 Answers 4

Reset to default
4

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...

Improve this answer
Sign up to request clarification or add additional context in comments.

2 Comments

Thanks. It turned out that I needed to add an index after all, which is the first thing I would suspected if SSMS was not so fast (and it tuning advisor didn't tell me that everything is fine). Is it possible that SSMS's speed may have had something to do with caching as you've suggested? I doubt that's it's a flushing problem since a new session is created for this query only.
If it is the only query in the session, it is not a flushing problem. Caching in Sql Server may lead to non reproducible performance problems. Also note: first results may be displayed quickly in SSMS, while the query is still running...
3

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

Improve this answer

3 Comments

There is no N+1 problem, it loads values into an anonymous type, no entities.
This is look like a N+1 problem :)
no, a query with a "select new ..." clause is always translated into exactly one sql query.
2

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.

Improve this answer

7 Comments

I've had the same problem: stackoverflow.com/questions/5664113/… as Pedro said- this is probably due to the fact you're loading and hydrating so many objects.
Thanks. But I don't believe that loading 4000 anonymous objects (projected properties are two Int64 values) should be a problem for NHibernate (there is nothing much to proxy there)? And yes, NHibernate LOG level is set to DEBUG, but there is single query line logged (the one in the question), so I am also pretty sure no eager loading occurs either. Since query returns immediately in SSMS, all NHibernate should do is wrap those returned pairs into instances of that anonymous type.
can you try the same query with stateless session?
Yes @Groo, you've got a point. Have you profiled SQL Server to see the query execution time?
I can't imagine that it has anything to do with eager loading, 1st level cache, proxies and stuff like this. It is just loading values and puts them into an anonymous type. There is nothing in the cache about it, because they are no entities. Log-level DEBUG actually may really hurt performance, not for the query itself, but the processing of the result.
|
2

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

Improve this answer

Comments

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.