Apparent race condition with 2nd level cache expiries

Hibernate ORM
1

Hello,
We’re migrating an application from Hibernate 5.5.8 to 6.4.4 (and ehcache from 3.9.4 to 3.10.8:jakarta)
Some of our entities are annotated with:

@Entity
@Cacheable
@Proxy(lazy = false)
@BatchSize(size = 512)
@Inheritance(strategy = InheritanceType.SINGLE_TABLE)
@Cache(usage = CacheConcurrencyStrategy.READ_WRITE)
@DiscriminatorColumn(discriminatorType = DiscriminatorType.STRING, name = "type")

And they have several one to many associations:

@ManyToOne(fetch = FetchType.LAZY, optional = false)
@Fetch(FetchMode.SELECT)
MyEntity getXyz() {

Since we have @Proxy(lazy = false) loading one of the entities typically ends up loading quite a few others, which is as expected. We see some most of these loaded happen in batches thanks to @BatchSize(size = 512). So it might take a few seconds to execute queries loading these entities.

With Hibernate 6.4.4 we occasionally have errors with this type of stacktrace:

Caused by: org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [x.y.z.MyEntity#19518]
	at org.hibernate.boot.internal.StandardEntityNotFoundDelegate.handleEntityNotFound(StandardEntityNotFoundDelegate.java:26)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:212)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:694)
	at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:710)
	at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:219)
	at org.hibernate.cache.spi.entry.CacheEntryHelper.assemble(CacheEntryHelper.java:75)
	at org.hibernate.cache.spi.entry.StandardCacheEntryImpl.assemble(StandardCacheEntryImpl.java:132)
	at org.hibernate.loader.ast.internal.CacheEntityLoaderHelper.convertCacheEntryToEntity(CacheEntityLoaderHelper.java:445)
	at org.hibernate.loader.ast.internal.CacheEntityLoaderHelper.processCachedEntry(CacheEntityLoaderHelper.java:318)
	at org.hibernate.loader.ast.internal.CacheEntityLoaderHelper.loadFromSecondLevelCache(CacheEntityLoaderHelper.java:259)
	at org.hibernate.loader.ast.internal.CacheEntityLoaderHelper.loadFromSecondLevelCache(CacheEntityLoaderHelper.java:203)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:573)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.EntitySelectFetchInitializer.initializeInstance(EntitySelectFetchInitializer.java:195)
	at org.hibernate.sql.results.internal.InitializersList.initializeInstance(InitializersList.java:70)
	at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:109)
	at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:86)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:181)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunk(MultiKeyLoadChunker.java:152)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunks(MultiKeyLoadChunker.java:97)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.initializeEntities(EntityBatchLoaderInPredicate.java:146)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:97)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:114)
	at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3748)
	at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3737)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.EntitySelectFetchInitializer.initializeInstance(EntitySelectFetchInitializer.java:195)
	at org.hibernate.sql.results.internal.InitializersList.initializeInstance(InitializersList.java:70)
	at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:109)
	at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:86)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:181)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunk(MultiKeyLoadChunker.java:152)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunks(MultiKeyLoadChunker.java:97)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.initializeEntities(EntityBatchLoaderInPredicate.java:146)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:97)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:114)
	at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3748)
	at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3737)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.EntitySelectFetchInitializer.initializeInstance(EntitySelectFetchInitializer.java:195)
	at org.hibernate.sql.results.internal.InitializersList.initializeInstance(InitializersList.java:70)
	at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:109)
	at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:86)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:181)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunk(MultiKeyLoadChunker.java:152)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunks(MultiKeyLoadChunker.java:97)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.initializeEntities(EntityBatchLoaderInPredicate.java:146)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:97)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:114)
	at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3748)
	at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3737)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.EntitySelectFetchInitializer.initializeInstance(EntitySelectFetchInitializer.java:195)
	at org.hibernate.sql.results.internal.InitializersList.initializeInstance(InitializersList.java:70)
	at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:109)
	at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:86)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:181)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunk(MultiKeyLoadChunker.java:152)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunks(MultiKeyLoadChunker.java:97)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.initializeEntities(EntityBatchLoaderInPredicate.java:146)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:97)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:114)
	at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3748)
	at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3737)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.AbstractBatchEntitySelectFetchInitializer.loadInstance(AbstractBatchEntitySelectFetchInitializer.java:182)
	at org.hibernate.sql.results.graph.entity.internal.BatchEntityInsideEmbeddableSelectFetchInitializer.lambda$endLoading$2(BatchEntityInsideEmbeddableSelectFetchInitializer.java:130)
	at java.base/java.util.HashMap.forEach(HashMap.java:1421)
	at org.hibernate.sql.results.graph.entity.internal.BatchEntityInsideEmbeddableSelectFetchInitializer.endLoading(BatchEntityInsideEmbeddableSelectFetchInitializer.java:127)
	at org.hibernate.sql.results.internal.InitializersList.endLoading(InitializersList.java:76)
	at org.hibernate.sql.results.internal.StandardRowReader.finishUp(StandardRowReader.java:114)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:209)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunk(MultiKeyLoadChunker.java:152)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunks(MultiKeyLoadChunker.java:97)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.initializeEntities(EntityBatchLoaderInPredicate.java:146)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:97)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:114)
	at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3748)
	at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3737)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.AbstractBatchEntitySelectFetchInitializer.loadInstance(AbstractBatchEntitySelectFetchInitializer.java:182)
	at org.hibernate.sql.results.graph.entity.internal.BatchEntitySelectFetchInitializer.lambda$endLoading$2(BatchEntitySelectFetchInitializer.java:97)
	at java.base/java.util.HashMap.forEach(HashMap.java:1421)
	at org.hibernate.sql.results.graph.entity.internal.BatchEntitySelectFetchInitializer.endLoading(BatchEntitySelectFetchInitializer.java:94)
	at org.hibernate.sql.results.internal.InitializersList.endLoading(InitializersList.java:76)
	at org.hibernate.sql.results.internal.StandardRowReader.finishUp(StandardRowReader.java:114)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:209)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunk(MultiKeyLoadChunker.java:152)
	at org.hibernate.loader.ast.internal.MultiKeyLoadChunker.processChunks(MultiKeyLoadChunker.java:97)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.initializeEntities(EntityBatchLoaderInPredicate.java:146)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:97)
	at org.hibernate.loader.ast.internal.AbstractEntityBatchLoader.load(AbstractEntityBatchLoader.java:55)
	at org.hibernate.loader.ast.internal.EntityBatchLoaderInPredicate.load(EntityBatchLoaderInPredicate.java:114)
	at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3748)
	at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3737)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
	at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
	at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
	at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:207)
	at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:246)
	at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:111)
	at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:68)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
	at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1222)
	at org.hibernate.internal.SessionImpl.internalLoad(SessionImpl.java:1068)
	at org.hibernate.sql.results.graph.entity.internal.AbstractBatchEntitySelectFetchInitializer.loadInstance(AbstractBatchEntitySelectFetchInitializer.java:182)
	at org.hibernate.sql.results.graph.entity.internal.BatchEntitySelectFetchInitializer.lambda$endLoading$2(BatchEntitySelectFetchInitializer.java:97)
	at java.base/java.util.HashMap.forEach(HashMap.java:1421)
	at org.hibernate.sql.results.graph.entity.internal.BatchEntitySelectFetchInitializer.endLoading(BatchEntitySelectFetchInitializer.java:94)
	at org.hibernate.sql.results.internal.InitializersList.endLoading(InitializersList.java:76)
	at org.hibernate.sql.results.internal.StandardRowReader.finishUp(StandardRowReader.java:114)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:209)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
	at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$2(ConcreteSqmSelectQueryPlan.java:137)
	at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:362)
	at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:303)
	at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:509)
	at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:427)
	... 6 more

The problematic entity definitively exists (it was created years ago).
This happens with the following isolated test code:

public class HibernateTest {	
	public static void main(String[] args) throws ParseException, InterruptedException {
		// bootstrap a session factory
		
		loadXyz();
		
		Thread.sleep(3000L); // The exception does not happen if this is removed

		loadAbc(); // The exception always happens here
	}

	private static void loadXyz() {
		try (Session session = ...openSession()) {
			// execute a query
		}
	}

	private static void loadAbc() {
		try (Session session = ...openSession()) {
			// execute another (different) query
		}
	}
}

And with the corresponding cache set to expire after 6 seconds:

    <cache alias="management.business.instrument.Instrument">
        <expiry>
            <tti unit="seconds">6</tti>
        </expiry>
        <heap>500000</heap>
    </cache>

The cache is not distributed and there are not other threads hitting the cache in the isolated example.
My understanding is that the query triggers the load of some entities which recursively load other entities, some from the cache and some others from the database.
I suspect that some entries might be expiring while this is happening but I can’t explain why this would be causing the issue.

In production we’re setting the cache expiry to 20 minutes and the problem rarely happens (a few times everyday). When it does happen and we retry immediately we see it happening again and then after a while it works fine again.

Could you please help me troubleshooting this issue?

2

Hi @gtoison, from the stack trace it looks like your analysis is correct: apparently you’re executing a query that in turn is batch-loading associated entities and this repeats quite a few times when eventually you get to the association with @Proxy(false) entity that is not found. Note that this annotation is deprecated in Hibernate 6 and we strongly discourage using it to avoid the infamous n + 1 problem, you can find more on this topic in our documentation.

We cannot know why this entity ends up not being loaded, thus triggering the not found exception. It would be nice to understand whether the final load is triggering a cache hit or is being loaded from the database: even if the cache were to expire while recursively loading associated entities we should be able to fallback to the datasource and return the correct instance.

It looks like you can reproduce this error with a simplified example. It would be great if you could create a simple project that demonstrates this issue, you can also use our test case templates, and when you have it please open new a jira issue.

3

Thank you for the answer @mbladel, I know this is not ideal and we’re having the (n+1) problem here, or even (n+1)^m because this happens recursively! But we had issues when we got proxies instead of initialized objects, this would break some instanceof tests so we’re currently making this trade-off.

From what I’ve seen when trying to debug the problem, Hibernate makes a jdbc batch load for the entity (and another one from the batch fetch queue) using MultiKeyLoadChunker but even though the SQL query seems right the entity is not returned by AbstractEntityBatchLoader

Would it be a bad idea to simulate a cache expiry by adding an interceptor (in the onLoad(...) method?) that calls sessionFactory.getCache().evict(...) in the middle of the loading process?
Or maybe evicting the entity from inside a org.hibernate.resource.jdbc.spi.StatementInspector?

I’ve seen that Hibernate has some tests using ehcache, but I worry that timing issues might complicate the reproduction.

Any advice or pointer is much appreciated!

4

I know this is not ideal and we’re having the (n+1) problem here

We give specific recommendations in our user guide about best practices when having to eagerly fetch associations, please refer to the link I sent you or even to the new Hibernate Introduction.

But we had issues when we got proxies instead of initialized objects, this would break some instanceof tests so we’re currently making this trade-off

Using instanceof with associations is strongly discouraged: you should make use of subclasses implementing methods in basic OOP logic, or at least use the dedicated org.hibernate.Hibernate#getClassLazy method to retrieve the type of lazy associations (note this might initialize the proxy though if inheritance is involved). You might even be interested in the new @ConcreteType annotation we’re planning to introduce further down the line, so stay tuned for that.

Would it be a bad idea to simulate a cache expiry by adding an interceptor

I don’t think it should be a problem, since we’re talking about entity cache here every single object load is an atomic read thus evicting between an entity load and the other should be fine. You can simply use jakarta’s @PostLoad entity lifecycle callback method or even register a org.hibernate.event.spi.PostLoadEventListener through sessionFactory.getEventEngine().getListenerRegistry().appendListeners( EventType.POST_LOAD, ... ).

5

Contrary to what I initially thought this does not seem to be a race condition. As you said the cache loads are atomic so it would have been surprising.

What matters seems to be which entities are present (or absent) in the 2nd level cache.

I created and issue here: [HHH-17918] - Hibernate JIRA
A reproducer here: HHH-17918 reproducer by gtoison · Pull Request #8103 · hibernate/hibernate-orm · GitHub
The reproducer seems to be failing with an error similar to what I’m getting in production and in my isolated code sample: hibernate-orm-pipeline/PR-8103 #1 test - Build / s390x_h2 / Test / testCacheEviction(EntityManagerFactoryScope) [Jenkins]