nHibernate enumerating the same collection on multiple threads

Question

I have a production application (IIS8, MVC5, nHibernate DAL) and I'm noticing high CPU usage as of late. Cycling the app pool fixes it but after doing some diagnostics and memory dumps from the server to analyze the issue, I noticed a consistent pattern of multiple threads trying to enumerate the same collection. The most common point is where the app checks the roles of the user. I suspect this might be more do to the fact that this code is ran for every request to verify permissions, so it's more likely to be the collection it gets stuck on?

public IList<Role> GetRoles(string username)
{
    var login = GetLoginForUser(username);
    return !login.Groups.Any() ? new List<Role>() : login.Groups.SelectMany(x => x.Roles).OrderBy(x => x.DisplayName).ToList();
}

My CurrentUser object there is a simple interface containing the details of the user, injected from a dependency resolver. I have verified that the UserId is present and valid, it's all pretty straight forward. When I took a look at the dumps of when these two requests were hung, I got a warning that multiple threads were enumerating a collection. When I checked the two threads in the dump, I saw practically identical stack traces. (I've renamed some of the namespace details in the stack trace but it's otherwise unaltered). The userId (and resulting profile) in both requests are the same, so it appears it's due to two separate threads trying to load the same object from the database at practically the same time.

The stack trace is below, but I'm not sure where to go from here in order to fix this.

System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].FindEntry(System.__Canon)+129 
System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].TryGetValue(System.__Canon, System.Nullable`1<Int32> ByRef)+12 
NHibernate.AdoNet.ColumnNameCache.GetIndexForColumnName(System.String, NHibernate.AdoNet.ResultSetWrapper)+25 
NHibernate.AdoNet.ColumnNameCache.GetIndexForColumnName(System.String, NHibernate.AdoNet.ResultSetWrapper)+25 
NHibernate.AdoNet.ResultSetWrapper.GetOrdinal(System.String)+e 
NHibernate.AdoNet.ResultSetWrapper.GetOrdinal(System.String)+e 
NHibernate.Type.NullableType.NullSafeGet(System.Data.IDataReader, System.String)+29 
NHibernate.Type.NullableType.NullSafeGet(System.Data.IDataReader, System.String[], NHibernate.Engine.ISessionImplementor, System.Object)+16 
NHibernate.Type.NullableType.NullSafeGet(System.Data.IDataReader, System.String[], NHibernate.Engine.ISessionImplementor, System.Object)+16 
NHibernate.Persister.Collection.AbstractCollectionPersister.ReadKey(System.Data.IDataReader, System.String[], NHibernate.Engine.ISessionImplementor)+14 
NHibernate.Persister.Collection.AbstractCollectionPersister.ReadKey(System.Data.IDataReader, System.String[], NHibernate.Engine.ISessionImplementor)+14 
NHibernate.Loader.Loader.ReadCollectionElement(System.Object, System.Object, NHibernate.Persister.Collection.ICollectionPersister, NHibernate.Loader.ICollectionAliases, System.Data.IDataReader, NHibernate.Engine.ISessionImplementor)+34 
NHibernate.Loader.Loader.ReadCollectionElement(System.Object, System.Object, NHibernate.Persister.Collection.ICollectionPersister, NHibernate.Loader.ICollectionAliases, System.Data.IDataReader, NHibernate.Engine.ISessionImplementor)+34 
NHibernate.Loader.Loader.ReadCollectionElements(System.Object[], System.Data.IDataReader, NHibernate.Engine.ISessionImplementor)+d2 
NHibernate.Loader.Loader.ReadCollectionElements(System.Object[], System.Data.IDataReader, NHibernate.Engine.ISessionImplementor)+d2 
NHibernate.Loader.Loader.GetRowFromResultSet(System.Data.IDataReader, NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, NHibernate.LockMode[], NHibernate.Engine.EntityKey, System.Collections.IList, NHibernate.Engine.EntityKey[], Bo+ab 
NHibernate.Loader.Loader.GetRowFromResultSet(System.Data.IDataReader, NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, NHibernate.LockMode[], NHibernate.Engine.EntityKey, System.Collections.IList, NHibernate.Engine.EntityKey[], Bo+ab 
NHibernate.Loader.Loader.DoQuery(NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, Boolean)+1e7 
NHibernate.Loader.Loader.DoQuery(NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, Boolean)+1e7 
NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, Boolean)+7f 
NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, Boolean)+7f 
NHibernate.Loader.Loader.LoadCollection(NHibernate.Engine.ISessionImplementor, System.Object, NHibernate.Type.IType)+de 
NHibernate.Loader.Loader.LoadCollection(NHibernate.Engine.ISessionImplementor, System.Object, NHibernate.Type.IType)+de 
NHibernate.Loader.Collection.CollectionLoader.Initialize(System.Object, NHibernate.Engine.ISessionImplementor)+1c 
NHibernate.Loader.Collection.CollectionLoader.Initialize(System.Object, NHibernate.Engine.ISessionImplementor)+1c 
NHibernate.Persister.Collection.AbstractCollectionPersister.Initialize(System.Object, NHibernate.Engine.ISessionImplementor)+1e 
NHibernate.Persister.Collection.AbstractCollectionPersister.Initialize(System.Object, NHibernate.Engine.ISessionImplementor)+1e 
NHibernate.Event.Default.DefaultInitializeCollectionEventListener.OnInitializeCollection(NHibernate.Event.InitializeCollectionEvent)+16d 
NHibernate.Impl.SessionImpl.InitializeCollection(NHibernate.Collection.IPersistentCollection, Boolean)+1fa 
NHibernate.Collection.AbstractPersistentCollection.Initialize(Boolean)+2f 
NHibernate.Collection.AbstractPersistentCollection.Read()+d 
NHibernate.Collection.Generic.PersistentGenericBag`1[[System.__Canon, mscorlib]].System.Collections.Generic.IEnumerable<T>.GetEnumerator()+11 
System_Core_ni!System.Linq.Enumerable+<SelectManyIterator>d__14`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].MoveNext()+10c 
System_Core_ni!System.Linq.Buffer`1[[System.__Canon, mscorlib]]..ctor(System.Collections.Generic.IEnumerable`1<System.__Canon>)+d9 
System_Core_ni!System.Linq.OrderedEnumerable`1+<GetEnumerator>d__0[[System.__Canon, mscorlib]].MoveNext()+6f 
System_Core_ni!System.Linq.OrderedEnumerable`1+<GetEnumerator>d__0[[System.__Canon, mscorlib]].MoveNext()+6f 
mscorlib_ni!System.Collections.Generic.List`1[[System.__Canon, mscorlib]]..ctor(System.Collections.Generic.IEnumerable`1<System.__Canon>)+17e 
System_Core_ni!System.Linq.Enumerable.ToList[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>)+3b 
Company.ApplicationServices.SecurityService.GetRoles(System.String)+ef 

I'm currently opening my database transaction in an ActionFilter that opens the transaction when OnActionExecuting() happens, and then commit/rollback the transaction when OnActionExecuted() happens.

I'm using StructureMap (v2.6.4.1) for my dependency injection, and the relevant lines for my data persistence is as follows.

var cfg = Fluently.Configure()
    .Database(MsSqlConfiguration.MsSql2008.ConnectionString(c => c.FromConnectionStringWithKey("DatabaseConnectionString"))
    .CurrentSessionContext<WebSessionContext>()
    // ... etc etc....
    .Cache(c => c.ProviderClass<NHibernate.Caches.SysCache2.SysCacheProvider>()
                .UseQueryCache()
                .UseSecondLevelCache()
                .UseMinimalPuts());

For<NHibernate.Cfg.Configuration>().Singleton().Use(cfg);
For<NHibernate.ISessionFactory>().Singleton()
    .Use(ctx =>
        {
            try
            {
                var config = ctx.GetInstance<NHibernate.Cfg.Configuration>();
                return config.BuildSessionFactory();
            }
            catch (SqlException ex)
            {
                ctx.GetInstance<IExceptionLogger>().Error(ex);
                throw;
            }
        });
For<NHibernate.ISession>().HybridHttpOrThreadLocalScoped()
    .Use(ctx => ctx.GetInstance<NHibernate.ISessionFactory>().OpenSession());

UPDATE: I'm still dealing with this and would love some tips on if this is a problem with nhibernate, or how I have it configured? I had the app lockup to the point where we had to reboot to server today because of 19 separate threads trying to enumerate the same collection.

It is mentioned below that it's likely a problem with lifetime scoping of the SecurityService, which I agree is a possibility. Currently I have the services being provided through dependency injection via Structuremap (last version of 2.6 released, haven't updated to 3.x yet). The details of which I've details briefly below for what I hope is succinct but still relevant.

public class SecurityService : ISecurityService
{
    private readonly IRepository<Login> loginRepository;

    public IList<Role> GetCurrentUserRoles()
    {
        var login = GetLoginForCurrentUser();
        return GetRoles(login.Name);
    }

    public Login GetLoginForCurrentUser()
    {
        //Some logic to derive the current UserId {guid} via some resources injected into this service class.

        return loginRepository.GetReference(loginId);
    }
}

public class NHibernateRepository<T> : IRepository<T> where T : class
{
    protected ISession Session { get; set; }

    public NHibernateRepository(ISession session)
    {
        Session = session;
    }

    public T GetReference(object id)
    {
        return Session.Get<T>(id);
    }

    // Other methods typical of a repository class, nothing special
}

My dependency resolver setup....

For<ISecurityService>().Use<SecurityService>();
For(typeof (IRepository<>)).Use(typeof (NHibernateRepository<>));
//And then the ISession is commented above.

nHibernate is configured with an internal context of WebSessionContext ISessionFactory is Singleton ISession is HybridHttpOrThreadLocalScoped ISecurityService and the IRepository are both both left t the default of Transient

The roles are cached and if are not found then the system makes the call to the GetRoles method on the security service, I think I might have an issue with it calling GetRoles more often than it needs to, but that's outside of the scope of the multiple concurrent enumeration problem I'm having now.

UPDATE: So I'm baffled, I got the same issue today for a call to GetReference. 18 separate threads stuck enumerating the same collection, but this one was internal to nHibernate.

System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].FindEntry(System.__Canon)+129 
System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].TryGetValue(System.__Canon, System.Nullable`1 ByRef)+12 
NHibernate.AdoNet.ColumnNameCache.GetIndexForColumnName(System.String, NHibernate.AdoNet.ResultSetWrapper)+25 
NHibernate.AdoNet.ResultSetWrapper.GetOrdinal(System.String)+e 
NHibernate.Type.NullableType.NullSafeGet(System.Data.IDataReader, System.String)+29 
NHibernate.Type.NullableType.NullSafeGet(System.Data.IDataReader, System.String[], NHibernate.Engine.ISessionImplementor, System.Object)+16 
NHibernate.Type.AbstractType.Hydrate(System.Data.IDataReader, System.String[], NHibernate.Engine.ISessionImplementor, System.Object)+14 
NHibernate.Persister.Entity.AbstractEntityPersister.Hydrate(System.Data.IDataReader, System.Object, System.Object, NHibernate.Persister.Entity.ILoadable, System.String[][], Boolean, NHibernate.Engine.ISessionImplementor)+3ce 
NHibernate.Loader.Loader.LoadFromResultSet(System.Data.IDataReader, Int32, System.Object, System.String, NHibernate.Engine.EntityKey, System.String, NHibernate.LockMode, NHibernate.Persister.Entity.ILoadable, NHibernate.Engine.ISessionImplementor)+118 
NHibernate.Loader.Loader.InstanceNotYetLoaded(System.Data.IDataReader, Int32, NHibernate.Persister.Entity.ILoadable, NHibernate.Engine.EntityKey, NHibernate.LockMode, System.String, NHibernate.Engine.EntityKey, System.Object, System.Collections.IList, NHi+8c 
NHibernate.Loader.Loader.GetRow(System.Data.IDataReader, NHibernate.Persister.Entity.ILoadable[], NHibernate.Engine.EntityKey[], System.Object, NHibernate.Engine.EntityKey, NHibernate.LockMode[], System.Collections.IList, NHibernate.Engine.ISessionImpleme+129 
NHibernate.Loader.Loader.GetRowFromResultSet(System.Data.IDataReader, NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, NHibernate.LockMode[], NHibernate.Engine.EntityKey, System.Collections.IList, NHibernate.Engine.EntityKey[], Bo+97 
NHibernate.Loader.Loader.DoQuery(NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, Boolean)+1e7 
NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(NHibernate.Engine.ISessionImplementor, NHibernate.Engine.QueryParameters, Boolean)+7f 
NHibernate.Loader.Loader.LoadEntity(NHibernate.Engine.ISessionImplementor, System.Object, NHibernate.Type.IType, System.Object, System.String, System.Object, NHibernate.Persister.Entity.IEntityPersister)+f3 
NHibernate.Loader.Entity.AbstractEntityLoader.Load(NHibernate.Engine.ISessionImplementor, System.Object, System.Object, System.Object)+22 
NHibernate.Loader.Entity.AbstractEntityLoader.Load(System.Object, System.Object, NHibernate.Engine.ISessionImplementor)+12 
NHibernate.Persister.Entity.AbstractEntityPersister.Load(System.Object, System.Object, NHibernate.LockMode, NHibernate.Engine.ISessionImplementor)+69 
NHibernate.Event.Default.DefaultLoadEventListener.LoadFromDatasource(NHibernate.Event.LoadEvent, NHibernate.Persister.Entity.IEntityPersister, NHibernate.Engine.EntityKey, NHibernate.Event.LoadType)+84 
NHibernate.Event.Default.DefaultLoadEventListener.DoLoad(NHibernate.Event.LoadEvent, NHibernate.Persister.Entity.IEntityPersister, NHibernate.Engine.EntityKey, NHibernate.Event.LoadType)+1d7 
NHibernate.Event.Default.DefaultLoadEventListener.Load(NHibernate.Event.LoadEvent, NHibernate.Persister.Entity.IEntityPersister, NHibernate.Engine.EntityKey, NHibernate.Event.LoadType)+5e 
NHibernate.Event.Default.DefaultLoadEventListener.ReturnNarrowedProxy(NHibernate.Event.LoadEvent, NHibernate.Persister.Entity.IEntityPersister, NHibernate.Engine.EntityKey, NHibernate.Event.LoadType, NHibernate.Engine.IPersistenceContext, System.Object)+73 
NHibernate.Event.Default.DefaultLoadEventListener.ProxyOrLoad(NHibernate.Event.LoadEvent, NHibernate.Persister.Entity.IEntityPersister, NHibernate.Engine.EntityKey, NHibernate.Event.LoadType)+cb 
NHibernate.Event.Default.DefaultLoadEventListener.OnLoad(NHibernate.Event.LoadEvent, NHibernate.Event.LoadType)+120 
NHibernate.Impl.SessionImpl.FireLoad(NHibernate.Event.LoadEvent, NHibernate.Event.LoadType)+140 
NHibernate.Impl.SessionImpl.Get(System.String, System.Object)+148 
NHibernate.Impl.SessionImpl.Get(System.Type, System.Object)+121 
NHibernate.Impl.SessionImpl.Get[[System.__Canon, mscorlib]](System.Object)+143 
Intellitive.Data.Repositories.NHibernateRepository`1[[System.__Canon, mscorlib]].GetReference(System.Object)+38

There was more after the call to GetReference but it's not really related to the problem from what I can tell?

Answer 1

To me it looks like you are using NHibernate older than 4.0.0 (released 17 August 2014). If you are using newer version just ignore this answer.

There was a concurrency issue with NHibernate - see here:

Sometimes our IIS process starting to use 100% CPU. In a memory dump we see that lots of threads is in the Dictionary FindEntry method, that is called from the ColumnNameCache.GetIndexForColumnName.

This has been resolved but patch has been merged only to version 4.0.0.

The problem was that generic Dictionary is getting into infinite loop when underlying collection has been modified, i.e. two threads are trying to read value and one is writing.

From documentation:

A Dictionary can support multiple readers concurrently, as long as the collection is not modified. Even so, enumerating through a collection is intrinsically not a thread-safe procedure. In the rare case where an enumeration contends with write accesses, the collection must be locked during the entire enumeration. To allow the collection to be accessed by multiple threads for reading and writing, you must implement your own synchronization.

Thread-unsafe version: https://github.com/nhibernate/nhibernate-core/blob/3.4.x/src/NHibernate/AdoNet/ColumnNameCache.cs

The same with applied patch: https://github.com/nhibernate/nhibernate-core/blob/master/src/NHibernate/AdoNet/ColumnNameCache.cs

Longer explanation of why Dictionary is not thread-safe and why IIS stops serving requests:

1. http://blogs.msdn.com/b/tess/archive/2009/12/21/high-cpu-in-net-app-using-a-static-generic-dictionary.aspx
2. http://improve.dk/debugging-in-production-part-2-latent-race-condition-bugs/
3. ASP.NET Hang - Generic Dictionary concurrency issues causes GC deadlock

Answer 2

This issue would have one culprit: the Company.ApplicationServices.SecurityService, which lifetime would over-cross the WebRequest/ISession life cycle.

Some assumptions

The SecurityService method is doing some magical (not shown in the quesiton above) call to ISession, recieving Login object.

In case that Login contains Groups (first iteration), it does continue to iterate it and load many Roles.

public IList<Role> GetRoles(string username)
{
    // the instance of login is loaded, still referencing some ISession
    var login = GetLoginForUser(username);
    return !login.Groups.Any()  // first iteration over Groups
         ? new List<Role>() 
         // second iteration 
         : login
            .Groups
            .SelectMany(x => x.Roles) // other iterations
            .OrderBy(x => x.DisplayName)
            .ToList();
}

This call is obviously very expensive from perspective of resource consumption. So there must be some caching somewhere (keep roles per thread at least, but maybe longer)

Most likely SecurityService is a singleton. But that would mean, that it has its own ISession. And such ISession would hardly be dependent on the Web Request(s). And that means, that it could have ever lasting session.

It could happen, that it returns the same login instance two many different threads (many Web Requests processed by different threads)

Similar story:

I would suggest to take a look on this Q & A and its discussion: Nhibernate Lazy Load exception after a view exception. The issue, problem cause, was different, but the solution should be the same.

Suggestion:

The above assumptions, even if they are correct only partially, should help to understand this suggestion below. In a nutshell, we should avoid sharing any objects from one ISession... with other threads/requests...

What we can see, is the issue with iterating object coming from one ISession, inside of other thread. The solution I do like: use Prototype pattern. (Pattern sovling issue expensive object creation/loading)

• let's load the Roles by username in one shot
• clone them (prototype) into level we need
• cache them, later return cached clones
• introduce some refreshing (after 2 minutes, sql cache dependeny, file dependency) to keep security objects in cache for a short/reasonable time only

There could be even other approaches (e.g. init all properties with NHibernateUtil.Initialize() and skipping the Clone)... but I can confirm, that Cloning is working well for me.

Quick overview:

class Group : ICloneable
{
    ...
    public override object Clone()
    {
        var entity = base.Clone() as Group;
        entity.Roles = new List<Role>();
        foreach(var r in Roles)
        {
           entity.Roles.Add(r.Clone() as Role);
        }
        ...
        return entity;
    }
}

class Login: ICloneable
{
    ...
    public override object Clone()
    {
        var entity = base.Clone() as Login;
        entity.Groups = new List<Group>();
        foreach(var g in Group)
        {
           entity.Groups.Add(r.Clone() as Group);
        }
        ...
        return entity;
    }
}

Nice is, that this draft above is in our hands. We can adjust the Cloned part as we need. At the end we can have a Clone, loaded once, independent on any session, having just properties needed for security... ready for caching

EXTEND: Based on more information in the extended question

I would say, that related to my guesses above, there is the culprit (at least suspected):

The roles are cached ...

But these roles are related to a session. They were not detached. They where just recieved via Linq on top of Login instance returned by ISession:

login.Groups.SelectMany(x => x.Roles).OrderBy(x => x.DisplayName).ToList()

Each of these objects (Login, Group, Role) is still attached to session in which it has born.

Meanwhile, at the same time, different web requests are coming. Different web requests for the same login (partial views, Web API calls). So, in multi-thread environment, more web requests can touch the cached roles and work with them. With these which are still related to existing, opened ISession, but on a different thread.

Most likely your framework is using these intensively to decide what to show and what to hide, what to edit...

So among many web requests, there is shared object (set of objects) related to another ISession.

My suggestion: Detach these objects. And the way I found the more accurate is the Protype pattern.

So, I believe that this should give you insight how these issues could happen, but what I want to emphasize is solution. Do not share objects related to one session among more requests/threads. Clone is just one way. But the principal is a key.