2nd level cache GetMany ineffective for collections

[EngSayed]

I believe there is an issue in second level cache when NHibernate initializing a collection which call GetMany to get all values for array of keys but then when it goes into for loop to Assemble then it again calls GetMany for each item

I have Entity which has a bag collection of EntityFields and both have batch-size=2000 attribute. When I try to load the collection EntityFields then NHibernate calls DefaultInitializeCollectionEventListener.InitializeCollectionFromCache then it gets a 2000 CacheKey which calls GetMany() till that point everything is fine but then it goes inside CacheEntry.Assemble which calls InternalLoad and DoLoad which again tries to load from the cache LoadFromSecondLevelCache and calls again GetMany ... attached the call stack image.

My understanding is that once it found it all in Second Level Cache then it should not keep calling GetMany again for each record one by one, right?

[bahusoid]

What version of NHibernate is used? Did you check with latest (5.4.2) version?

[EngSayed]

What version of NHibernate is used? Did you check with latest (5.4.2) version?

Version 5.2.7
When I checked the code of latest version, I didn't see a difference in that area, do you?

[bahusoid]

Yes I do. Check with latest version.

[EngSayed]

Ok, I will try to check with latest, hopefully there are no breaking changes as it will take longer time then to check.

[EngSayed]

After trying to upgrade to version 5.4.2, I keep getting

Could not load file or assembly 'NHibernate, Version=5.2.0.0, Culture=neutral, PublicKeyToken=aa95f207798dfdb4' or one of its dependencies. The located assembly's manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)

=== Pre-bind state information ===
LOG: DisplayName = NHibernate, Version=5.2.0.0, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
Calling assembly : NHibernate.Caches.StackExchangeRedis, Version=5.9.0.0, Culture=neutral, PublicKeyToken=6876f2ea66c9f443.

I have added assembly binding redirect but still keep getting the same error. Any idea how to solve that?

      <dependentAssembly>
        <assemblyIdentity name="NHibernate" publicKeyToken="AA95F207798DFDB4" culture="neutral"/>
        <bindingRedirect oldVersion="0.0.0.0-5.2.0.0" newVersion="5.4.2.0"/>
      </dependentAssembly>

[EngSayed]

I fixed the version issue by redirecting to version 5.4.0.0

      <dependentAssembly>
        <assemblyIdentity name="NHibernate" publicKeyToken="aa95f207798dfdb4" culture="neutral"/>
        <bindingRedirect oldVersion="0.0.0.0-5.4.0.0" newVersion="5.4.0.0"/>
      </dependentAssembly>
      <dependentAssembly>

@bahusoid, After upgrading to version 5.4.3 (latest) issue is still the same, after calling GetMany() for all then it goes one by one and again call object[] GetMany(CacheKey[] keys, long timestamp) while keys of size 1 key only. This is very time consuming while having already more than 60,000 item cached in Redis now it will go one by one for all of them

[EngSayed]

I enabled NHibernate Logging and here is part of the logs, you can see that it fetched all, then got Cache hit but then after that it went again for each record (one by one) to load, attempting to resolve, fetch from cahce, cache hit and resolved

2023-07-14 23:45:21,876 - collection initialized from cache
2023-07-14 23:46:16,311 - initializing collection [EntityRelationship.RelationshipLinks#1]
2023-07-14 23:46:16,312 - checking second-level cache
2023-07-14 23:46:16,333 - Cache lookup: EntityRelationship.RelationshipLinks#1,EntityRelationship.RelationshipLinks#4,....
...
2023-07-14 23:46:16,335 - Fetching 2000 objects...
2023-07-14 23:46:16,337 - Fetching object with key: '{NHibernate-Cache:entities}-1:EntityRelationship.RelationshipLinks#1'.
2023-07-14 23:46:16,337 - Fetching object with key: '{NHibernate-Cache:entities}-1:EntityRelationship.RelationshipLinks#4'.
...
2023-07-14 23:46:16,966 - Cache hit: EntityRelationship.RelationshipLinks#1
2023-07-14 23:46:16,967 - Cache hit: EntityRelationship.RelationshipLinks#4
...
2023-07-14 23:48:44,853 - Collection cache hit: EntityRelationship.RelationshipLinks#4
2023-07-14 23:48:44,855 - loading entity: [EntityRelationshipLink#4]
2023-07-14 23:48:44,925 - attempting to resolve: [EntityRelationshipLink#4]
2023-07-14 23:48:44,926 - Cache lookup: EntityRelationshipLink#4
2023-07-14 23:48:44,926 - Fetching 1 objects...
2023-07-14 23:48:44,926 - Fetching object with key: '{NHibernate-Cache:entities}-1:EntityRelationshipLink#4'.
2023-07-14 23:48:44,986 - Cache hit: EntityRelationshipLink#4
2023-07-14 23:48:53,184 - Entity cache hit: EntityRelationshipLink#4
2023-07-14 23:48:53,184 - assembling entity from second-level cache: [EntityRelationshipLink#4]
2023-07-14 23:48:53,187 - loading entity: [EntityRelationship#4]
2023-07-14 23:48:53,188 - attempting to resolve: [EntityRelationship#4]
2023-07-14 23:48:53,189 - resolved object in session cache: [EntityRelationship#4]
NHIbernate Cache Bug Log.txt

[EngSayed]

In ResolveIdentifier method, you already lost the cached value

PersistentGenericBag<T>

		/// <summary>
		/// Initializes this PersistentBag from the cached values.
		/// </summary>
		/// <param name="persister">The CollectionPersister to use to reassemble the PersistentBag.</param>
		/// <param name="disassembled">The disassembled PersistentBag.</param>
		/// <param name="owner">The owner object.</param>
		public override void InitializeFromCache(ICollectionPersister persister, object disassembled, object owner)
		{
			var array = (object[]) disassembled;
			var size = array.Length;
			BeforeInitialize(persister, size);
			for (var i = 0; i < size; i++)
			{
				var element = persister.ElementType.Assemble(array[i], Session, owner);
				if (element != null)
				{
					_gbag.Add((T) element);
				}
			}
		}

ManyToOneType.cs:

		public override object Assemble(object oid, ISessionImplementor session, object owner)
		{
			//TODO: currently broken for unique-key references (does not detect
			//      change to unique key property of the associated object)

			object id = AssembleId(oid, session);

			if (id == null)
			{
				return null;
			}
			else
			{
				return ResolveIdentifier(id, session);
			}
		}

EntityType.cs:

		/// <summary>
		/// Resolves the identifier to the actual object.
		/// </summary>
		protected object ResolveIdentifier(object id, ISessionImplementor session)
		{
			string entityName = GetAssociatedEntityName();
			bool isProxyUnwrapEnabled = unwrapProxy && session.Factory
			                                                  .GetEntityPersister(entityName).IsInstrumented;

			object proxyOrEntity = session.InternalLoad(entityName, id, eager, IsNullable && !isProxyUnwrapEnabled);

			if (proxyOrEntity.IsProxy())
			{
				INHibernateProxy proxy = (INHibernateProxy) proxyOrEntity;
				proxy.HibernateLazyInitializer.Unwrap = isProxyUnwrapEnabled;
			}

			return proxyOrEntity;
		}

[hazzik]

@EngSayed what NHibernate.Caches version do you have?

[EngSayed]

@EngSayed what NHibernate.Caches version do you have?

"NHibernate.Caches.StackExchangeRedis" Version 5.9.0

[EngSayed]

@hazzik, to me, the bug is inside NHibernate core not inside NHibernate.Caches.
NHibernate is not passing the loaded cached values while trying to Load the collection entity

[hazzik]

I'm just trying to eliminate variables from the equation.

[hazzik]

If you could design a simplest test case it would be great.

[bahusoid]

NHibernate calls DefaultInitializeCollectionEventListener.InitializeCollectionFromCache then it gets a 2000 CacheKey which calls GetMany()
then it goes inside CacheEntry.Assemble which calls InternalLoad and DoLoad which again tries to load from the cache LoadFromSecondLevelCache and calls again GetMany

Multiple GetMany calls are expected - collections are cached as list of identifiers. So first (InitializeCollectionFromCache) we retrieve list of ids in collection then we load full entities by id (LoadFromSecondLevelCache).

But of course, we shouldn't load collection entities one by one. We should batch it.
Test case for BatchableCacheFixture:

[Test]
public void CollectionLazyInitializationFromCacheIsBatched()
{
	int count;

	using (var s = OpenSession())
	{
		var readOnly = s.Get<ReadOnly>(s.Query<ReadOnly>().Select(x => x.Id).First());
		count = readOnly.Items.Count;
	}
	var itemPersister = Sfi.GetEntityPersister(typeof(ReadOnlyItem).FullName);
	var itemCache = (BatchableCache) itemPersister.Cache.Cache;
	itemCache.ClearStatistics();


	using (var s = OpenSession())
	{
		var readOnly = s.Get<ReadOnly>(s.Query<ReadOnly>().Select(x => x.Id).First());
		count = readOnly.Items.Count;
	}

	// 6 items with batch-size = 4 so 2 GetMany calls are expected 1st call: 4 items + 2nd call: 2 items
	Assert.That(itemCache.GetMultipleCalls.Count, Is.EqualTo(2));
}

P.S. That's all from me - I'm not working on a fix.

[EngSayed]

Multiple GetMany calls are expected - collections are cached as list of identifiers. So first (InitializeCollectionFromCache) we retrieve list of ids in collection then we load full entities by id (LoadFromSecondLevelCache).

But of course, we shouldn't load collection entities one by one. We should batch it. Test case for BatchableCacheFixture:

But in the first GetMany you already loaded all values so why after to keep calling Get/GetMany for each record?