Ioannis Panagopoulos blog

Tutorials on HTML5, Javascript, WinRT and .NET

Domain Driven Design, Business Objects, Datasets, NHibernate and friend Jack (Part 2/2)

by Ioannis Panagopoulos

 

In the previous post, we have discussed some issues that emerged from a conversation with my friend Jack. In this post we will explore a little bit his following statement:

Jack: Well(…) I have created a BO (a simple one, mapped to a single table in the DB) and created a very simple DataLayer using NHibernate to retrieve a list of 1500 BOs and display them in a DataGrid. It took NHibernate 6 sec to retrieve the data! Can you believe it? (…) I have tried the same thing with a DataSet and it took only some msec (…)  I tried to find a solution to this in the internet for 3 hours and found nothing. NHibernate is poorly documented too… Nothing beats DataSets.

This needs proof. This needs code. So I have implemented a small application as my testbench to perform my measurement with NHibernate. The TestBench is as follows:

We create a small DB in MS SQL with a single table and 20000 records:

As you can see the table consists of a Primary Key (ID – Bigint) and 5 columns with strings (String1..5) of type nvarchar(50).

Now we go to Visual Studio, create a new application and implement the Business Object as follows (this is what Jack did):

 

That is we provide a Property and a Field for every column in the Table. The FirePropertyChangedNotification(value) method is at the parent GenericBO class and is implemented as follows:

Which is the typical BO’s support of the INotifyPropertyChanged interface needed for updating the GUI correctly in data binding scenarios.

The next thing was to set up NHibernate and provide the mapping file between the table and the BO:

Now it was time to perform some tests. I decided to test several ways of retrieving the list of TestClass BOs both with NHibernate Session and SessionStateless. So the tests are as follows (all tests return List<TestClass> unless explicitly specified):

 

I got the following times (for test 3 to work I needed to specify a property ID named as the column in the Table in TestClass whose accessors are accessing the field _primaryKey) :

  Test 1 Test 2 Test 3 Test 4
1st Time 26,078sec 23,927 sec 23,113 sec 23,735 sec
2nd Time 0,117 sec 0,098 sec 23,050 sec 0,106 sec
Times include time to display in WPF DataGrid

The results are disappointing. Of course the second time, since there is no change in the Cache the times are very low (in Test3 the times are the same for the first and second time since we are performing a plain mapping with a transformer) but what happens in the first Time? Will we have better lack if we perform the same tests in a StateLess session?

  Test 1 Test 2 Test 3 Test 4
1st Time 25,573sec 24,890sec 24,531sec N/A
2nd Time 25.041 sec 25,029 sec 23,427sec N/A
Times include time to display in WPF DataGrid

Now we are worse off. First and Second time are huge due to the absence of the cache. Was Jack right after all? Before jumping into conclusions let’s enable logging for NHibernate and see the log:

Retrieval starts at:

2009-02-11 21:41:05,268 [10] DEBUG NHibernate.Loader.Loader - processing result set
2009-02-11 21:41:05,268 [10] DEBUG NHibernate.Loader.Loader - result set row: 0
2009-02-11 21:41:05,274 [10] DEBUG NHibernate.Loader.Loader - result row: EntityKey[ORMTests.TestClass#1]
2009-02-11 21:41:05,279 [10] DEBUG NHibernate.Loader.Loader - Initializing object from DataReader: [ORMTests.TestClass#1]
2009-02-11 21:41:05,285 [10] DEBUG NHibernate.Persister.Entity.AbstractEntityPersister - Hydrating entity: [ORMTests.TestClass#1]
 

First phase ends at:

2009-02-11 21:41:11,949 [10] DEBUG NHibernate.Loader.Loader - result set row: 19999
2009-02-11 21:41:11,949 [10] DEBUG NHibernate.Loader.Loader - result row: EntityKey[ORMTests.TestClass#20000]
2009-02-11 21:41:11,949 [10] DEBUG NHibernate.Loader.Loader - Initializing object from DataReader: [ORMTests.TestClass#20000]
2009-02-11 21:41:11,949 [10] DEBUG NHibernate.Persister.Entity.AbstractEntityPersister - Hydrating entity: [ORMTests.TestClass#20000]
2009-02-11 21:41:11,949 [10] DEBUG NHibernate.Loader.Loader - done processing result set (20000 rows)

First phase takes 6 seconds !

Second phase starts at:

2009-02-11 21:41:11,957 [10] DEBUG NHibernate.Engine.TwoPhaseLoad - resolving associations for [ORMTests.TestClass#1]
2009-02-11 21:41:11,962 [10] DEBUG NHibernate.Engine.TwoPhaseLoad - done materializing entity [ORMTests.TestClass#1]

Second phase ends at:

2009-02-11 21:41:32,601 [10] DEBUG NHibernate.Engine.TwoPhaseLoad - resolving associations for [ORMTests.TestClass#20000]
2009-02-11 21:41:32,602 [10] DEBUG NHibernate.Engine.TwoPhaseLoad - done materializing entity [ORMTests.TestClass#20000]

Second phase takes 21 seconds !

With a little research it seems that in the second phase NHibernate performs the mapping of the raw values to the Business Objects. To verify that we run Test 3 again but this time we do not map the results to BOs: 

 

Now the time has decreased to : 1 sec !

There must be a delay when mapping the data to the BOs. So I have manually added the code to map the data to the TestClass Business Objects just after getting the List<object> ListReturned as follows: 

 

The retrieval time returned to 15,227sec which is an improvement from 23sec but still not acceptable.

So the problem is not with NHibernate but rather it is in the way we have implemented the BO. And the first suspicious place where this may be happening is when calling the FirePropertyChangedNotification(…). So we first remove from the function the automatic retrieval of the Property’s name which may cause the delay:

(StateLess Session)

  Test 1 Test 2 Test 3 Test 4
1st Time 8,855sec 8,827sec 4,651sec N/A
2nd Time 8,638sec 8,815sec 4,170sec N/A
Times include time to display in WPF DataGrid

We have 50% increase in performance. How about removing the method call completely and putting its behavior directly in the properties?

(StateLess Session)

  Test 1 Test 2 Test 3 Test 4
1st Time 0,813sec 0,510sec 0,331sec N/A
2nd Time 0,490sec 0,553sec 0,320sec N/A
Times include time to display in WPF DataGrid

Which is now acceptable. To make sure we try to load the same data using a DataSet which gives approximately 0,301sec.

The last thing to do is perform the comparison between Test2 and DataSets for increasing table size:

   

Apparently there is a difference in DataSets but now this difference is justified since NHibernate is an ORM tool which is more than a simple mapping tool which creates the DataSets.

As a conclusion, Jack was again wrong. Wrong, because it was his implementation that lead to this big stall in performance and not NHibernate itself. Moreover, when he was searching the internet for a solution it was normal not to be able to find one since the issue was caused by his way of implementing things.

My effort is not to advertise NHibernate. I am sure that the same would emerge with EDM or any other ORM tool. The point of this 2 post discussion is three-fold:

  • First to show a way of thinking which in my opinion can lead to overstatements.
  • Second to provide a general overview of DDD, ORM, DataSets and Business Objects.
  • Third to show some performance analysis results when using NHibernate and a way to resolve issues about those.

 

kick it on DotNetKicks.com
blog comments powered by Disqus
hire me