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.