External Issue
Details
Assignee
UnassignedUnassignedReporter
Gene TrogGene TrogComponents
Affects versions
Priority
MinorWho's Looking?
Open Who's Looking?
Details
Details
Assignee
Unassigned
UnassignedReporter
Gene Trog
Gene TrogComponents
Affects versions
Priority
Who's Looking?
Open Who's Looking?
Created March 20, 2013 at 7:48 PM
Updated March 22, 2013 at 4:20 PM
Resolved March 22, 2013 at 4:20 PM
I work at a company where we use NHibernate for persisting large amounts of data. In trying to optimize NHibernate performance by periodically evicting all entities from the first-level cache, I came across some strange behavior. My eviction policy simply consists of periodically checking how many entities are cached, and when it goes above a certain threshold, calling ISession.Clear(). The particular code in question makes use of ISession.Get<T>() heavily, which I expected (maybe wrongly so) would perform the fetch in constant time from the cache. It turns out as the number of entities that are cached increases, so does the time it takes for ISession.Get<T>() to execute, linearly so. Here's a simple program to demonstrate:
using (var readSession = factory.OpenSession())
{
const long maxItems = 10000;
object lastId = null;
Console.WriteLine("Generating objects...");
using (var tran = readSession.BeginTransaction())
{
for (int i = 0; i < maxItems; i++)
{
var foo = new Foo { Name = i.ToString() };
lastId = readSession.Save(foo);
}
tran.Commit();
readSession.Clear();
Console.WriteLine("Computing retrieval times...");
}
// gradually increase the number of entities in the first-level cache
for (long j = 0; j < maxItems; j += (maxItems / 10))
{
// fill cache with j items
readSession.Clear();
readSession.CreateCriteria<Foo>().SetMaxResults((int)j).List<Foo>();
// retrieve 100 of the same item
var dt = DateTime.Now;
for (long i = 0; i < 10000; i++)
{
readSession.Get<Foo>(lastId);
}
Console.WriteLine("Items in cache {0}: {1}", j, DateTime.Now - dt);
}
}
On my machine the output I have is:
Generating objects...
Computing retrieval times...
Items in cache 0: 00:00:00.0970000
Items in cache 1000: 00:00:00.9260000
Items in cache 2000: 00:00:01.7920000
Items in cache 3000: 00:00:02.6540000
Items in cache 4000: 00:00:03.4880000
Items in cache 5000: 00:00:04.3470000
Items in cache 6000: 00:00:05.2110000
Items in cache 7000: 00:00:06.2130000
Items in cache 8000: 00:00:06.8750000
Items in cache 9000: 00:00:07.7590000
Upon further investigation, I narrowed the 'culprit' down to the following code:
StatefulPersistenceContext.cs:325
/// <summary> Called after transactions end</summary>
public void AfterTransactionCompletion()
{
// Downgrade locks
foreach (EntityEntry entityEntry in entityEntries.Values)
entityEntry.LockMode = LockMode.None;
}
So here it's seemingly unnecessarily setting the lock mode on entities that may or may not have been even touched, and, sure enough, commenting out this code caused the constant time access I expected from ISession.Get<T>(). I don't know much about the internals of NHibernate, so I don't know the reasoning for iterating over every entity, but I imagine this could be improved upon by maybe tracking what entities need to have their locks downgraded after the transaction completes.