Concurrency issues since upgrade to 5.4.24

Hibernate ORM
1

Hi,
we are facing issues when updating to hibernate-core >= 5.4.24. By bisecting we identified that the problematic changes were introduced during fixing (HHH-14312). This fix was finished by 61dcb7dcd43dc1d2326911bdb11a52c54c6452b8

Unfortunately, we have not been able to boil things down to a very narrow reproducing test case. And what’s worst: Concurrency seems to be a problem. We can reproduce the erroneous behaviour quite easily when using multiple threads, never when running single threaded.

The error looks as follows. Do you have any hints what might be wrong? A lot of changes in the context of DynamicBatching which we are using were made while fixing HHH-14312. So it might be a bug as well.

Any hints for further steps for narrowing down the problem are appreciated.

Best regards, Jens

Exception:
    org.hibernate.exception.GenericJDBCException: could not extract ResultSet
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:67) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.getResultSet(AbstractLoadPlanBasedLoader.java:390) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:163) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:104) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.loadEntityBatch(AbstractLoadPlanBasedEntityLoader.java:233) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.loader.entity.plan.DynamicBatchingEntityLoader.load(DynamicBatchingEntityLoader.java:72) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:4441) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4431) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:569) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:537) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:208) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:103) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:74) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:113) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1186) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.internal.SessionImpl.immediateLoad(SessionImpl.java:1005) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:179) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:310) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    at [AND HERE OUR OWN CODE BEGINS]
    ...
Caused by: java.sql.SQLException: Fehlender IN- oder OUT-Parameter auf Index:: 5
    at oracle.jdbc.driver.OraclePreparedStatement.processCompletedBindRow(OraclePreparedStatement.java:1937) ~[ojdbc8.jar!/:19.8.0.0.0]
    at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3657) ~[ojdbc8.jar!/:19.8.0.0.0]
    at oracle.jdbc.driver.T4CPreparedStatement.executeInternal(T4CPreparedStatement.java:1426) ~[ojdbc8.jar!/:19.8.0.0.0]
    at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3713) ~[ojdbc8.jar!/:19.8.0.0.0]
    at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1167) ~[ojdbc8.jar!/:19.8.0.0.0]
    at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504) ~[?:?]
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57) ~[hibernate-core-5.4.24.Final.jar:5.4.24.Final]
    ... 474 more
2

The commit you posted does not seem to affect concurrency. Also, the error suggests that this happens when doing lazy loading. I don’t know how your setup looks like, but are you aware that Session can not be shared between threads?

3

Thanks for your hint regarding Session sharing.

We logged all the Session ids in SessionFactoryImp#getCurrentSession() and checked that no Session is used in more than one thread. Everything looked fine to us.

Do you have another idea for what we could watch out for?

Still wondering why the changes mentioned above should trigger this change in behaviour.

4

Since this is about lazy loading, it’s necessary to understand that “managed” entities are connected to an open session. If you share an entity object with another thread and then trigger lazy loading, this will cause issues. To avoid this, you will have to detach the entity from the session. Just note that you might then run into a LazyInitializationException though, so you will have to ensure that the state you require is either initialized, or you reattach the entity with the session of the current thread by doing entityManager.merge(entity) or entityManager.refresh(entity).

5

Okay, seems like that we have found the root cause for this issue…

The SQLExceptions in our stack trace are caused by incorrect batchsizes for EntityLoader#Builder. This results in incorrect number of parameters being generated into prepared SQL statements for loading entities. Sometimes we face too many parameter placeholders like mentioned above, sometimes too few.

<tldr>EntityLoader$Builder is not thread safe and should not be used concurrently</tldr>

The identical DynamicBatchingEntityLoader (i.e. the same object ID) is used in several threads at the same time.This object contains an EnityLoader$Builder (obviously same object ID as well) which is used to build the EntityLoader. The batch size is set on the builder according to the number of ids that has to be loaded in DynamicBatchingEntityLoader#.load() before the factory method EntityLoader.Builder.byPrimaryKey () is called. So there is a window of vulnerability between setting the batch size and generating the SQL string. If on a different thread the batch size is set to a different value we are in trouble.

It is still not completely clear to us why exactly the identical DymamicBatchingEntityLoader can be used on several threads simultaneously. The solution to the question can probably be found in AbstractEntityPersister.doLoad(). The method getAppropriateLoader() is called there. In our case always the last branch is taken (getLoaderByLockMode()). This does not respect the current session.

The changeset mentioned in our initial message is most likely not responsible for the problems observed. I would rather expect HHH-14271 Lazy initialization of UniqueEntityLoader for most LockMode… · hibernate/hibernate-orm@81d526e · GitHub to be the source. Some caching and lazy initialization for EnitityLoaderBuilders seems to have been introduced there.

The changes for [HHH-14312]([HHH-14312] Padded batch style entity loader ignores entity graph - Hibernate JIRA we initially suspected just made the pre-existing bug much more likely to occurr in our situation. While fixing HHH-14312 a special treatment for batchsize = 1 was eliminated. This leads to a larger number of calls to withBatchSize() and therefore a higher potential for collisions.

Does this sound reasonable?
If no: Could we just be holding it wrong and by this cause getAppropriateLoader() return inappropriate stuff? Would you need more information to understand better what is going wrong?
If yes: How should we proceed? Will you file a bug or should we do that? How likely is a fix for this issue for the next release?

6

Thanks for the detailed analysis, this is indeed a bug. The builder should not be shared. I created [HHH-14471] Concurrency issue in DynamicBatchingEntityLoader - Hibernate JIRA

7

Can you verify that this fixes your issue? HHH-14471 Fix concurrency issue due to builder sharing in DynamicBatchingEntityLoader by beikov · Pull Request #3766 · hibernate/hibernate-orm · GitHub

1 Like
8

Did the verification and left a comment in the issue.

Thanks for fixing!

Do you have a rough estimate for when a release containing the fix will be available?

9

It’s hard to say, but we usually try to release once per month, so maybe you will get this with the next 5.4 release.

10

I have the same issue :frowning: