Description
Carsten Hess created an issue — 2nd July 2008, 13:36:07:
Going from 1.2.0 to 2.0beta1 I unfortunately see that the autoflush functionality (checking for dirty entities) is dramatically slower in 2.0. The time spent in dirtycheck is at least a factor 10 slower (and it wasn't fast in 1.2). I have attached a screen clipping from DotTrace where you can see that 625 calls to SessionImpl.List ends up in 218.719 calls to OnFlushEntity which ends up in 3.492.076 calls to NHibernate.Properties.FieldAccessor.Get
This corresponds to almost 40% of the total time which is too expensive.
Carsten Hess added a comment — 2nd July 2008, 21:53:28:
The whole thing triggering my analysis is that my integration test-suite went from 13 to 37 minutes when I upgraded to 2.0b1.
In order to show that autoflush check got slower in 2.0, I added 2 new screenshot for Session.UniqueResult. They show that in
1.2:
336 calls to UniqueResult takes 36 sec.
336 calls to AutoFlushIfRequired takes 80% (also a very high amount) corresponding to 29 sec.2.0
336 calls to UniqueResult now takes 76 sec
336 calls to AutoFlushIfRequired takes 95,5% corresponding to 72 sec.
Carsten Hess added a comment — 9th July 2008, 5:42:41:
The headline of this improvement is actually misleading as it is not the auto-flush mode mechanism in it self which is much slower in 2.0, but the dirty-check, which unfortunately means that it affects all kinds of flushing!
Fabio Maulo added a comment — 12th July 2008, 17:28:13:
mmm... yes and not...
In NH2.0.0 you can override the DefaultAutoFlushEventListener to do what you want.
Many application don't work using auto-flush different than FlushMode.Never.
Many app. use version and there the dirty check work only with one property.BTW I we would check if there is a really possibility to have better performance for this issue.
Carsten Hess added a comment — 28th July 2008, 6:23:06:
Hello Fabio.
I am sad about title I originally gave to this issue - because it is not restricted to autoflush - its simply related to the dirty check.
I would imagine that a lot of applications are using FlushMode = FlushMode.Commit and they are indeed hit by this issue!!
So I'm really glad that you will investigate for better performance (and off course that you spend so much of your time on this super product as NHibernate is). Right now I can't afford (performance-wise) to upgrade from 1.2 due to this issue.
Kind regards
Carsten Hess
Fabio Maulo added a comment — 28th July 2008, 9:41:00:
Probably the solution is more simple than appear....
News soon.
Fabio Maulo added a comment — 28th July 2008, 10:27:39:
What you are doing with 626 calls to AutoFlush ?
In which environment you are using dotTrace ? I mean... How many long is your session ?AutoFlush is called each time you are querying something and you have some not-readonly entities in the session.
We can check performance but really I think you are using NH in a wrong way.
In NH2.0 you have many others features and 336 calls to UniqueResult in the same session are really something strange.
Please use our users group (http://groups.google.com/group/nhusers) to explain what you doing, sometimes you need help and there is another solution to improve performance of your app.P.S. I check the result of DotTrace.
Carsten Hess added a comment — 29th July 2008, 10:43:47:
I totally agree that its not a normal situation - the run is from a test - not from production-code. We normally don't do so nearly as much work in a session.
I just used it to make a point that 2.0 is a great deal slower at flushing than 1.2.
I understand when autoflush is called - but the important thing in the example is not that it is in autoflush mode - the point is that the session needs to flush - and the necessary FLUSH takes much longer time as in 1.2. So I would have seen the same performance problem if I had used Flushmode.Commit.
Perhaps I can make a more realistic scenario for you with flushmode.Commit and "normal" use of a session if you are interested ?
Kind regards
Carsten
Fabio Maulo added a comment — 29th July 2008, 14:20:51:
Sure I'm interest in a test that show the problem.
If you want you can use LogSpy (a class of NH test) in a test more closer to the real use of NH.
Thanks.
Jalal added a comment — 30th April 2009, 10:27:17:
what would happen if I moved the line to
public virtual void OnAutoFlush(AutoFlushEvent @event) { IEventSource source = @event.Session; if (FlushMightBeNeeded(source)) { int oldSize = source.ActionQueue.CollectionRemovalsCount; //FlushEverythingToExecutions(@event); // <---------------- move this line to the next line after the check. if (FlushIsReallyNeeded(@event, source)) { FlushEverythingToExecutions(@event); // <---------------- To here if (log.IsDebugEnabled) log.Debug("Need to execute flush"); .....This will control the AutoFlush issue to do it once Really needed .... nice for longer sessions which would benefit from session cache. I know you Fabio hate this approach ... but it is used from BLUK updates. Just image creating a new session for inserting/updating a record in a 100,000 record batch process.
Trent Niemeyer added a comment — 16th November 2009, 9:53:11:
Agree that this is an issue. We turned off AutoFlush, when I realized what was going on. HUGE difference. I don't like Jalal's solution so much, because I think the problem is more fundamental. Why does NH have to iterate through the entire entity collection on a dirty check? If it knows when properties are set in session, why not just keep track of things that are dirty?
Pawel Smolarkiewicz added a comment — 7th January 2010, 22:55:38:
I agree that flush performance in NH 2.X should be improved, to clarify (as noted in a previous comment). The issue is NOT limited to AutoFlush, it appears that the "dirty checking" during any flush (explicit, on commit, or auto) is quite expensive.
ayenderahien added a comment — 7th January 2010, 23:09:12:
I would say that this indicates that we need to improve our dirty checking implementation and see if we can optimize that.
I'll look deeper into this.