Skip to content

2nd level cache GetMany ineffective for collections #3359

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
EngSayed opened this issue Jul 13, 2023 · 42 comments · Fixed by #3365
Closed

2nd level cache GetMany ineffective for collections #3359

EngSayed opened this issue Jul 13, 2023 · 42 comments · Fixed by #3365

Comments

@EngSayed
Copy link

EngSayed commented Jul 13, 2023

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?

Stack

@bahusoid

This comment was marked as resolved.

@EngSayed

This comment was marked as resolved.

@bahusoid

This comment was marked as resolved.

@EngSayed

This comment was marked as resolved.

@EngSayed

This comment was marked as resolved.

@EngSayed

This comment was marked as resolved.

@EngSayed
Copy link
Author

EngSayed commented Jul 17, 2023

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
Copy link
Author

EngSayed commented Jul 17, 2023

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

This comment was marked as resolved.

@EngSayed

This comment was marked as resolved.

@EngSayed
Copy link
Author

EngSayed commented Jul 17, 2023

@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
Copy link
Member

hazzik commented Jul 17, 2023

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

@hazzik
Copy link
Member

hazzik commented Jul 17, 2023

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

@bahusoid
Copy link
Member

bahusoid commented Jul 17, 2023

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
Copy link
Author

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?

@hazzik
Copy link
Member

hazzik commented Jul 17, 2023

But in the first GetMany you already loaded all values

Collection cache contains only entity ids, not entities itself.

@EngSayed
Copy link
Author

But in the first GetMany you already loaded all values

Collection cache contains only entity ids, not entities itself.

Ah OK now I got it. So at first it gets all collection ids but then it should run in batches to load values for the collections themselves.
Can we get a fix for this bug please as it is making it very slow and sometimes timeout to load data from the cache defeating the main concept of caching unfortunately

@hazzik
Copy link
Member

hazzik commented Jul 17, 2023

@bahusoid

But of course, we shouldn't load collection entities one by one. We should batch it.

I think we can reuse parts of query cache for this.

@EngSayed, I would suggest not using collection caches. Often, from practice it is faster to load collection from DB than from L2 cache. This is a know problem.

@EngSayed
Copy link
Author

@bahusoid

But of course, we shouldn't load collection entities one by one. We should batch it.

I think we can reuse parts of query cache for this.

@EngSayed, I would suggest not using collection caches. Often, from practice it is faster to load collection from DB than from L2 cache. This is a know problem.

That's very bad news indeed!! Every Entity has collection(s) and if I would load collection from DB then why not to also load the entity from DB as well?

@hazzik
Copy link
Member

hazzik commented Jul 17, 2023

Ok, turns out the fix is super easy...

@bahusoid thanks for the test.

@hazzik hazzik added p: Major and removed p: Minor labels Jul 17, 2023
@hazzik hazzik added this to the 5.4.4 milestone Jul 17, 2023
@hazzik hazzik changed the title NHibernate PersistentGenericBag InitializeCollectionFromCache AbstractPersistentCollection InitializeCollectionFromCache performance Jul 17, 2023
@EngSayed
Copy link
Author

@hazzik, @bahusoid, thanks for the fix. I see that it is labeled with version 5.4.4, any idea when will it be released?

@hazzik hazzik removed the r: Fixed label Jul 18, 2023
@hazzik
Copy link
Member

hazzik commented Jul 18, 2023

any idea when will it be released?

Not sure when. You should be able to try a pre-release version as soon as PR is merged

hazzik added a commit that referenced this issue Jul 18, 2023
@hazzik
Copy link
Member

hazzik commented Jul 18, 2023

Fixed #3365

@EngSayed
Copy link
Author

any idea when will it be released?

Not sure when. You should be able to try a pre-release version as soon as PR is merged

PR is merged, how to get the pre-release version please?

@bahusoid
Copy link
Member

It's going to be published by our nightly build to cloudsmith tomorrow: https://cloudsmith.io/~nhibernate/repos/nhibernate-core/packages/

See https://github.com/nhibernate/nhibernate-core#nightly-development-builds

Wait for next 5.4.4-dev build or compile it yourself from sources.

@bahusoid
Copy link
Member

@EngSayed
Copy link
Author

Fix available in: https://cloudsmith.io/~nhibernate/repos/nhibernate-core/packages/detail/nuget/NHibernate/5.4.4-dev.4462/

Thanks. I will try to test it later.
Any due date for the release 5.4.4?

@fredericDelaporte
Copy link
Member

No. We do not have schedules for releases. We do them when they are ready, and when a contributor is available to do the release.

@EngSayed
Copy link
Author

@hazzik, @bahusoid, I tested the fix but unfortunately it behaves the same.

@bahusoid
Copy link
Member

Are you sure 5.4.4-dev.4462/ is used? Logs?

@EngSayed
Copy link
Author

Yes, and same logs

2023-07-24 17:07:48,049 - Cache lookup: Entities.EntityField#88499,Entities.EntityField#88500,Entities.EntityField#88501,Entities.EntityField#88502,Entities.EntityField#88503,Entities.EntityField#88504,Entities.EntityField#88505,Entities.EntityField#88506,Entities.EntityField#88507,Entities.EntityField#88508,Entities.EntityField#88509,Entities.EntityField#88510,Entities.EntityField#88511,Entities.EntityField#88512,Entities.EntityField#88513,Entities.EntityField#88514,Entities.EntityField#88515,Entities.EntityField#88516,Entities.EntityField#88517,Entities.EntityField#88518,Entities.EntityField#88519,Entities.EntityField#88520,Entities.EntityField#88521,Entities.EntityField#88522,Entities.EntityField#88523,Entities.EntityField#88524,Entities.EntityField#88525,Entities.EntityField#88526,Entities.EntityField#88890
2023-07-24 17:07:48,049 - Fetching 29 objects...
2023-07-24 17:07:48,050 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88499'.
2023-07-24 17:07:48,050 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88500'.
2023-07-24 17:07:48,051 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88501'.
2023-07-24 17:07:48,052 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88502'.
2023-07-24 17:07:48,052 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88503'.
2023-07-24 17:07:48,053 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88504'.
2023-07-24 17:07:48,053 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88505'.
2023-07-24 17:07:48,054 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88506'.
2023-07-24 17:07:48,054 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88507'.
2023-07-24 17:07:48,055 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88508'.
2023-07-24 17:07:48,055 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88509'.
2023-07-24 17:07:48,056 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88510'.
2023-07-24 17:07:48,056 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88511'.
2023-07-24 17:07:48,057 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88512'.
2023-07-24 17:07:48,057 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88513'.
2023-07-24 17:07:48,058 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88514'.
2023-07-24 17:07:48,058 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88515'.
2023-07-24 17:07:48,058 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88516'.
2023-07-24 17:07:48,059 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88517'.
2023-07-24 17:07:48,059 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88518'.
2023-07-24 17:07:48,060 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88519'.
2023-07-24 17:07:48,060 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88520'.
2023-07-24 17:07:48,060 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88521'.
2023-07-24 17:07:48,061 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88522'.
2023-07-24 17:07:48,062 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88523'.
2023-07-24 17:07:48,062 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88524'.
2023-07-24 17:07:48,063 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88525'.
2023-07-24 17:07:48,063 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88526'.
2023-07-24 17:07:48,064 - Fetching object with key: '{NHibernate-Cache:entitiesMetadata}-1:Entities.EntityField#88890'.
2023-07-24 17:07:48,068 - Cache hit: Entities.EntityField#88499
2023-07-24 17:07:48,068 - Cache hit: Entities.EntityField#88500
2023-07-24 17:07:48,069 - Cache hit: Entities.EntityField#88501
2023-07-24 17:07:48,069 - Cache hit: Entities.EntityField#88502
2023-07-24 17:07:48,070 - Cache hit: Entities.EntityField#88503
2023-07-24 17:07:48,070 - Cache hit: Entities.EntityField#88504
2023-07-24 17:07:48,071 - Cache hit: Entities.EntityField#88505
2023-07-24 17:07:48,071 - Cache hit: Entities.EntityField#88506
2023-07-24 17:07:48,071 - Cache hit: Entities.EntityField#88507
2023-07-24 17:07:48,072 - Cache hit: Entities.EntityField#88508
2023-07-24 17:07:48,073 - Cache hit: Entities.EntityField#88509
2023-07-24 17:07:48,073 - Cache hit: Entities.EntityField#88510
2023-07-24 17:07:48,074 - Cache hit: Entities.EntityField#88511
2023-07-24 17:07:48,074 - Cache hit: Entities.EntityField#88512
2023-07-24 17:07:48,075 - Cache hit: Entities.EntityField#88513
2023-07-24 17:07:48,076 - Cache hit: Entities.EntityField#88514
2023-07-24 17:07:48,076 - Cache hit: Entities.EntityField#88515
2023-07-24 17:07:48,077 - Cache hit: Entities.EntityField#88516
2023-07-24 17:07:48,077 - Cache hit: Entities.EntityField#88517
2023-07-24 17:07:48,078 - Cache hit: Entities.EntityField#88518
2023-07-24 17:07:48,078 - Cache hit: Entities.EntityField#88519
2023-07-24 17:07:48,079 - Cache hit: Entities.EntityField#88520
2023-07-24 17:07:48,079 - Cache hit: Entities.EntityField#88521
2023-07-24 17:07:48,079 - Cache hit: Entities.EntityField#88522
2023-07-24 17:07:48,080 - Cache hit: Entities.EntityField#88523
2023-07-24 17:07:48,080 - Cache hit: Entities.EntityField#88524
2023-07-24 17:07:48,081 - Cache hit: Entities.EntityField#88525
2023-07-24 17:07:48,081 - Cache hit: Entities.EntityField#88526
2023-07-24 17:07:48,082 - Cache hit: Entities.EntityField#88890
2023-07-24 17:07:48,082 - assembling entity from second-level cache: [Entities.EntityField#88500]
2023-07-24 17:07:48,083 - loading entity: [Entities.Entity#81880]
2023-07-24 17:07:48,083 - attempting to resolve: [Entities.Entity#81880]
2023-07-24 17:07:48,084 - resolved object in session cache: [Entities.Entity#81880]
2023-07-24 17:07:48,084 - Cached Version: 
2023-07-24 17:07:48,084 - initializing non-lazy collections
2023-07-24 17:07:48,085 - assembling entity from second-level cache: [Entities.EntityField#88501]
2023-07-24 17:07:48,086 - loading entity: [Entities.Entity#81880]
2023-07-24 17:07:48,086 - attempting to resolve: [Entities.Entity#81880]
2023-07-24 17:07:48,086 - resolved object in session cache: [Entities.Entity#81880]
2023-07-24 17:07:48,087 - Cached Version: 
2023-07-24 17:07:48,087 - initializing non-lazy collections
2023-07-24 17:07:48,088 - assembling entity from second-level cache: [Entities.EntityField#88502]
2023-07-24 17:07:48,088 - loading entity: [Entities.Entity#81880]
2023-07-24 17:07:48,089 - attempting to resolve: [Entities.Entity#81880]
2023-07-24 17:07:48,089 - resolved object in session cache: [Entities.Entity#81880]

@EngSayed
Copy link
Author

Here are part of Monitor logs from Redis:

1690213541.670176 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12862"
1690213541.670267 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12862" "86400000"
1690213541.670357 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13303"
1690213541.670459 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13303" "86400000"
1690213541.670549 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12863"
1690213541.670656 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12863" "86400000"
1690213541.670754 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13304"
1690213541.670849 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13304" "86400000"
1690213541.670959 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12864"
1690213541.671059 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12864" "86400000"
1690213541.671150 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13305"
1690213541.671242 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13305" "86400000"
1690213541.671440 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12865"
1690213541.671580 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#12865" "86400000"
1690213541.671677 [1 lua] "get" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13306"
1690213541.671769 [1 lua] "pexpire" "{NHibernate-Cache:entitiesMetadata}-1:.Entities.EntityRelationship.RelationshipLinks#13306" "86400000"

As you can see it goes one by one not batches and I have default_batch_fetch_size = 25

@bahusoid
Copy link
Member

bahusoid commented Jul 24, 2023

I see no one-by-one lookups for collection elements in your log. Parts like (from old log):

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

There was Cache lookup in your logs for each entity. I don't see it anymore

@bahusoid
Copy link
Member

Now it looks like in your log:

resolved object in session cache: [Entities.Entity#81880]

So entities are already preloaded to session.

@EngSayed
Copy link
Author

So why it keeps firing GetMany for only 1 cache key over and over?

@bahusoid
Copy link
Member

Don't know. Maybe incorrect cache configuration (not configured getmany script or something) It's all good from nhibernate-core part.

@EngSayed
Copy link
Author

Don't know. Maybe incorrect cache configuration (not configured getmany script or something) It's all good from nhibernate-core part.

That cannot be correct because for the main entity it fires get many for a batch of keys. The number of keys are calculated from nhibernate core so it is not good from this side

@EngSayed
Copy link
Author

Now it looks like in your log:

resolved object in session cache: [Entities.Entity#81880]

So entities are already preloaded to session.

This is the main entity not the collection. So it resolves the entity but it goes to Redis cache for the collection one by one

@EngSayed
Copy link
Author

EngSayed commented Jul 24, 2023

After debugging again I think I got what is happening ... so after it GetMany for the main entities, then it goes for each entity to load its collection and of course if the collection has more than one record then it GetMany that collection after that it goes to the second main Entity to load its collection and so on
so it better than before indeed.
Sorry for the confusion :)
Could you please release it :) our application is very big and I am enabling 2nd level cache to fix performance and cannot wait to test it widely :)

@EngSayed
Copy link
Author

@fredericDelaporte, any news on releaseing 5.4.4 ?

@dplaskon
Copy link

For whatever it's worth, this one is biting us too - would love to see a release to resolve this!

@fredericDelaporte fredericDelaporte changed the title AbstractPersistentCollection InitializeCollectionFromCache performance 2nd level cache GetMany ineffective for collections Jul 30, 2023
@fredericDelaporte
Copy link
Member

It is now released.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants