A performance regression in v5

[FransBouma]

Hi,

Using my raw dataaccess benchmarks (https://github.com/FransBouma/RawDataAccessBencher) which I just updated to include NHv5, latest stable, I saw the performance of NHibernate fell dramatically. v4.1 was slightly faster than EF6, but NHv5 is slower than EF6 and also consumes even more memory.

Below is a screenshot of the set fetch of 31K rows from AdventureWorks' SalesOrderHeader, synchronously in change tracked entities. I've expanded the tree to a location which illustrates that there's something seriously wrong: with 31K rows in a single query it's weird the code ends up 410,000 (!) times in the method which checks whether something has to be enlisted into an ambient transaction. There's just 1 (synchronous) query.

You can easily profile the benchmarked fetches with a profiler, just uncomment this line: https://github.com/FransBouma/RawDataAccessBencher/blob/master/RawBencher/OriginalController.cs#L77 and follow the directions on screen.

Hope this helps to gain some insight what to fix. Cheers.

[hazzik]

@FransBouma can you make the same screenshot for the NH 4.1?

[fredericDelaporte]

There is also the 58.66% part which is not deployed which could be interesting to see.

[hazzik]

I've expanded the tree to a location which illustrates that there's something seriously wrong: with 31K rows in a single query it's weird the code ends up 410,000 (!) times

That the quote above should be just:

there's something seriously wrong ... 31K rows in a single query.

My guess is that 410,000 figure is the number of entities being fetched.

[fredericDelaporte]

Thanks for the notice.

While the redundant CheckAndUpdateSessionStatus can certainly be changed for being way less fired (maybe with some "depth" counter in the session entry points for disabling it for sub-operations), this thing is nothing new. But it does some more checking in v5, like the transaction enlistment.

From what I read on the above screenshot, the transaction enlistment check would represent a 4% impact. It does not seem to be enough for being responsible of the "dramatic performance drop". It may be easy to check: if transaction scopes are not used, just configure the AdoNetTransactionFactory to be used instead of the default transaction factory. This will remove the transaction enlistment check.

Extracted from @FransBouma result files, here are the results for various things.

Test	NH v4 (2017-10-24)	NH v5 (2017-11-20)	%
Change tracking fetches, set fetches (50 runs), no caching	1.881,56ms, Enum: 2,32ms, 550.424KB	2.354,00ms, Enum: 2,14ms, 828.909KB	+25%ms, Enum: -8%, +50%KB
Change tracking individual fetches (100 elements, 50 runs), no caching	0,48ms, 80KB	0,53ms, 96KB	+10%ms, +20%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching	273,47ms, 73.273KB	361,18ms, 122.993KB	+32%ms, +68%KB

I hope the benchmark other conditions have not much changed between the two runs, otherwise comparing them would not make sens. (EF6 results stay similar in both runs, so I think comparing runs does make sens.)

[gliljas]

I've run the benchmark with NH4.1 (and DotTrace) and the 410K is there too. It's not (as we already agree) the culprit, but certainly something that should be addressed. The persistencecontext should not have to be retrieved 410k times.

[fredericDelaporte]

The factor between fetched rows and calls can be due to the CheckAndUpdateSessionStatus being call on access to things like the session PersistenceContext property or InitializeCollection method.

Since PersistenceContext is a property, it should not do much processing. Ideally a property get should be not much more than yielding a member. Maybe should we reconsider why CheckAndUpdateSessionStatus is called there. If we need to keep it, check if we can instead disable it when operations like querying is ongoing. Or maybe can we replace it by just ErrorIfClosed. It is somewhat weird to do such checking on a property otherwise just yielding a member: what prevents the code having retrieved the property value to change the session state before using that retrieved value?

[hazzik]

I'll make a PR with a reduced amount of calls to ISessionImplementor.PersistenceContext.

[hazzik]

No, it doesn't fetch the 410K entities,

Yeah, it does not. It has found 205K entities referenced (either as a FK or as a fetch). The ISessionImplementor.PersistenceContext method was called twice in ScheduleBatchLoadIfNeeded.

[gliljas]

Let's deal with the "compared to NH4.1" scenario, first and foremost.

[hazzik]

PS: Giving me (or anyone else) here a "thumbs down" wouldn't help.

[hazzik]

On my machine combined ISessionImplementor.PersistenceContext is responsible "only" for 6.48% of time. On the other hand SessionIdLoggingContext constructor + Dispose are responsible for 28.35% of time. So, this issue is already resolved by #1391

[hazzik]

Duplicate of #1391

[hazzik]

Here are the benchmark results for #1391 Benchmarks.zip

[fredericDelaporte]

1391 being an option to activate, I think we need to add an issue "switch that option on by default" for 6.0 milestone.

[hazzik]

I just did a memory profiling. The SessionIdLoggingContext is responsible for this enormous 800m objects allocations (in fact AsyncLocal), which again is going away with #1391

[hazzik]

@fredericDelaporte I think it is fine to release 5.1 with this option being disabled by default, otherwise, I'm considering to release 6.0 instead.

[fredericDelaporte]

Ok for both options. Doing it in 5.1 will imply putting a small "possible breaking change" in the notes, but with just a config switch to change for reverting it, I think it is ok to do it.

I am also willing to test something else but have not taken the time yet: change the using of the SessionIdLoggingContext into some using (BeginProcess()) where BeginProcess would belong to the abstract session, handle a depth level and do the session id stuff and the check status on first level only, then use that BeginProcess() instead of the using on SessionIdLoggingContext and instead of the calls to check status. The call to check status from properties would be an exception, where it would not do the using but just call the check status according to the current processing depth (if 0, called, otherwise not called). It would save most of the redundant checks and set session id calls we have currently, which could greatly reduces their impact even without completely disabling the session id stuff.

[hazzik]

I might have a fix for 5.0.2. Not sure though

[fredericDelaporte]

I am also willing to test something else but have not taken the time yet:...

Now done. 28% gain on ms (or 38% if using as base the best performing one), memory down from 830mb to 490mb. I have done a little more that what I was writing above. I will explain more in a PR. (I may not have time to do it this evening.)