NHibernate
The object-relational mapper for .NET
Note: this was originally posted on my own blog
One of the new features that NHibernate 2.0 introduced is NHibernate Statistics. This feature can be pretty useful during development (or while debugging) to keep an eye on what NHibernate is doing. Not a lot of people know about this feature, so i've decided to write a short series of posts about it. In this first episode, we'll explore some stats which can show you some useful information regarding the efficiency of your (simple) data fetching strategies. Later episodes will cover insert/update/delete statistics, query specific statistics and caching statistics. I don't know yet when the other episodes will be posted, but they are definitely on my TODO list so they will get written eventually ;)
First of all, here's how you can enable this feature. In your hibernate.cfg.xml file, you can add the following setting within the session-factory element.
<property name="generate_statistics">true</property>
Now, there are two levels of statistics. The first is at the level of the SessionFactory. These statistics basically keep count of everything that happens for each Session that was created by the SessionFactory. You can access these stats through the Statistics property of the SessionFactory instance, which you can access from your Session instance if you don't have a reference to the SessionFactory, for instance:
var count = Session.SessionFactory.Statistics.EntityFetchCount;
To give you an idea of what kind of stats are available on the SessionFactory level, here's a quick listing of most of the available properties:
EntityDeleteCount, EntityInsertCount, EntityLoadCount, EntityFetchCount, EntityUpdateCount, QueryExecutionCount, QueryExecutionMaxTime, QueryCacheHitCount, QueryCacheMissCount, QueryCachePutCount, FlushCount, ConnectCount, SecondLevelCacheHitCount, SecondLevelCacheMissCount, SecondLevelCachePutCount, SessionCloseCount, SessionOpenCount, CollectionLoadCount, CollectionFetchCount, CollectionUpdateCount, CollectionRemoveCount, CollectionRecreateCount, SuccessfulTransactionCount, TransactionCount, PrepareStatementCount, CloseStatementCount, OptimisticFailureCount.
There are even more properties and methods available. For instance to retrieve the executed queries, statistics for a specific query, statistics for a specific entity type, for a specific collection role, and to get the second level cache statistics for a specific cache region. As you can see, lots of useful properties to help you examine where your NHibernate usage might not be the way it should be. Or just useful in case you're tying to figure out what kind of stuff NHibernate is doing behind the scenes for features you don't fully understand and want to experiment with. There's also a useful LogSummary() method which (obviously) logs a summary of these stats to NHibernate's logger.
Let's get into a couple of examples that will tell us more about the efficiency of our simple data access strategies. We'll start with some really simple stuff, and then move to some more interesting statistics.
For brevity, i'm using the following simple property to quickly access the SessionFactory's statistics:
private IStatistics GlobalStats
{
get { return Session.SessionFactory.Statistics; }
}
For the first example, we'll retrieve all of the records in the Product table. After fetching this result, the EntityLoadCount statistic will reflect the number of entities we've loaded:
[Test]
public void TestEntityLoadCount()
{
long entityLoadCountBefore = GlobalStats.EntityLoadCount;
var allProducts = Session.CreateCriteria(typeof(Product)).List<Product>();
Assert.AreEqual(entityLoadCountBefore + allProducts.Count, GlobalStats.EntityLoadCount);
}
What happens if we start using NHibernate's lazy loading features? For instance, if we access a Product's Category reference NHibernate has to retrieve that record from the database if it's not already loaded. Does this count as an EntityLoad, or an EntityFetch? It counts as both an EntityLoad and an EntityFetch actually:
[Test]
public void TestEntityFetchCountForManyToOnePropertiesWithLazyLoading()
{
long entityLoadCountBefore = GlobalStats.EntityLoadCount;
long entityFetchCountBefore = GlobalStats.EntityFetchCount;
var allProducts = Session.CreateCriteria(typeof(Product)).List<Product>();
foreach (var product in allProducts)
{
// this makes NHibernate fetch the Category from the database
var categoryName = product.Category.Name;
}
var entitiesFetched = GlobalStats.EntityFetchCount - entityFetchCountBefore;
Assert.AreEqual(entityLoadCountBefore + allProducts.Count + entitiesFetched, GlobalStats.EntityLoadCount);
Assert.That(entitiesFetched != 0);
}
With the data in my database, this test loads 77 Product entities, and fetches 8 Categories for a total of 85 loaded entities. The Product entities are loaded in one roundtrip, but for each Category another roundtrip is performed which is not ideal from a performance perspective. The stats actually reflect that through the PrepareStatementCount property. Let's modify the previous test to highlight this:
var entitiesFetched = GlobalStats.EntityFetchCount - entityFetchCountBefore;
Assert.AreEqual(entityLoadCountBefore + allProducts.Count + entitiesFetched, GlobalStats.EntityLoadCount);
Assert.AreEqual(entitiesFetched + 1, GlobalStats.PrepareStatementCount);
Assert.That(entitiesFetched != 0);
We get the count of the fetched entities, and add 1 to it to reflect the roundtrip to fetch all the products. This total equals the value of the PrepareStatementCount property.
This example shows that it can be pretty important to try to keep the EntityFetchCount and PrepareStatementCount property values as low as possible when you need to fix a performance problem. Let's give it a shot:
[Test]
public void TestEntityFetchCountForManyToOnePropertiesWithoutLazyLoading()
{
long entityFetchCountBefore = GlobalStats.EntityFetchCount;
var allProducts = Session.CreateCriteria(typeof(Product))
.CreateCriteria("Category", JoinType.InnerJoin)
.List<Product>();
foreach (var product in allProducts)
{
// the Categories have already been retrieved, so this doesn't cause a db roundtrip
var categoryName = product.Category.Name;
}
var entitiesFetched = GlobalStats.EntityFetchCount - entityFetchCountBefore;
Assert.AreEqual(1, GlobalStats.PrepareStatementCount);
Assert.AreEqual(0, entitiesFetched);
}
Instead of fetching all of the Products and then relying on NHibernate's lazy loading to fetch the Categories, we fetch all of them in one go. The result is that NHibernate only performs one DB statement and it still loads all 85 records.
These statistics are nice if you just want to get information about loading entities, but what about collections? Well, we can use the CollectionLoadCount and CollectionFetchCount properties for this:
[Test]
public void TestCountsForOneToManyPropertyWithLazyLoading()
{
var loadCountBefore = GlobalStats.EntityLoadCount;
var collectionLoadCountBefore = GlobalStats.CollectionLoadCount;
var collectionFetchCountBefore = GlobalStats.CollectionFetchCount;
var prepareStatementCountBefore = GlobalStats.PrepareStatementCount;
var allRegions = Session.CreateCriteria(typeof(Region)).List<Region>();
var territoryCount = 0;
foreach (var region in allRegions)
{
// uses lazy-loading to fetch the Territories for this region
territoryCount += region.Territories.Count();
}
Assert.AreEqual(loadCountBefore + allRegions.Count + territoryCount, GlobalStats.EntityLoadCount);
Assert.AreEqual(collectionLoadCountBefore + allRegions.Count, GlobalStats.CollectionLoadCount);
Assert.AreEqual(collectionFetchCountBefore + allRegions.Count, GlobalStats.CollectionFetchCount);
Assert.AreEqual(prepareStatementCountBefore + allRegions.Count + 1, GlobalStats.PrepareStatementCount);
}
Btw, using the Count() result of the Territories property is something i'd never do, but i'm just using it here to illustrate these stats. In this case, we have 4 Regions, which we retrieve in one roundtrip, and then we fetch each Region's Territories in seperate trips which brings the total of PrepareStatementCount up to 5. As you can see, the CollectionLoadCount is equal to the CollectionFetchCount. In some cases, it can be better to retrieve the Territories while we're also retrieving the Regions:
[Test]
public void TestCountsForManyToOnePropertyWithoutLazyLoading()
{
var loadCountBefore = GlobalStats.EntityLoadCount;
var collectionLoadCountBefore = GlobalStats.CollectionLoadCount;
var collectionFetchCountBefore = GlobalStats.CollectionFetchCount;
var prepareStatementCountBefore = GlobalStats.PrepareStatementCount;
var allRegions = Session.CreateCriteria(typeof(Region))
.SetFetchMode("Territories", FetchMode.Join)
.SetResultTransformer(CriteriaUtil.DistinctRootEntity)
.List<Region>();
var territoryCount = 0;
foreach (var region in allRegions)
{
// the Territories have already been retrieved, so this doesn't use lazy-loading
territoryCount += region.Territories.Count();
}
Assert.AreEqual(loadCountBefore + allRegions.Count + territoryCount, GlobalStats.EntityLoadCount);
Assert.AreEqual(collectionLoadCountBefore + allRegions.Count, GlobalStats.CollectionLoadCount);
Assert.AreEqual(collectionFetchCountBefore, GlobalStats.CollectionFetchCount);
Assert.AreEqual(prepareStatementCountBefore + 1, GlobalStats.PrepareStatementCount);
}
With this code, there's only one roundtrip, yet all of the Regions and their Territories are loaded. This approach won't always be better than retrieving the collections seperately though... it kinda depends on the size and shape of the resultset of the joined query compared to the size and shapes of the resultsets of retrieving the root entities and their child collections seperately.
This post only showed a couple of the (many) interesting statistics that NHibernate can give you, but it could already help you troubleshoot bad-performing parts of your application. Keep an eye on those EntityFetchCount and PrepareStatementCount values... If the EntityFetchCount is rather low compared to the total EntityLoadCount, then there's probably nothing bad going on. If the EntityFetchCount is a rather large percentage of the total EntityLoadCount value, then you can be pretty sure that you can get some solid performance improvements in the code that drives up the EntityFetchCount value.