Details
-
Bug
-
Resolution: Done
-
Major
-
6.0.2.Final
-
None
Description
There is a related issue in the Hibernate JIRA, which can be found at:
https://hibernate.atlassian.net/browse/HHH-7898
However, I believe this to be an Infinispan issue, as per my analysis below.
The following Exception is thrown when two threads are simultaneously committing a JTA transaction in which an entry has been written to Hibernate's "replicated-query" cache using the same key.
10:55:02.238 ERROR saction.TransactionCoordinator - ISPN000255: Error while processing prepare org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [0 milliseconds] on key [sql: select ...; parameters: ...; named parameters: {...}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2] for requestor [GlobalTransaction:<null>:197882:local]! Lock held by [null] at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198) at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:169) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:98) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.lockAndRecord(OptimisticLockingInterceptor.java:211) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitSingleKeyCommand(OptimisticLockingInterceptor.java:206) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:199) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:270) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:75) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:36) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:114) at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:101) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:119) at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:101) at org.infinispan.transaction.synchronization.SynchronizationAdapter.beforeCompletion(SynchronizationAdapter.java:44) at com.metiom.core.transaction.TransactionImpl.lambda$commit$0(TransactionImpl.java:115) at com.metiom.core.transaction.TransactionImpl$$Lambda$2/330107372.accept(Unknown Source) at com.metiom.core.transaction.TransactionImpl.forEachSynchronisation(TransactionImpl.java:264) at com.metiom.core.transaction.TransactionImpl.commit(TransactionImpl.java:114) at com.metiom.core.transaction.TransactionManagerImpl.commit(TransactionManagerImpl.java:142) at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1021) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:757) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:726) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:497) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ...
The configuration for Hibernate's "replicated-query" cache is as follows (from Hibernate's infinispan-configs.xml)
<!-- An alternative configuration for entity/collection caching that uses replication instead of invalidation --> <namedCache name="replicated-entity"> <clustering mode="replication"> <stateTransfer fetchInMemoryState="false" timeout="20000"/> <sync replTimeout="20000"/> </clustering> <locking isolationLevel="READ_COMMITTED" concurrencyLevel="1000" lockAcquisitionTimeout="15000" useLockStriping="false"/> <!-- Eviction configuration. WakeupInterval defines how often the eviction thread runs, in milliseconds. 0 means the eviction thread will never run. A separate executor is used for eviction in each cache. --> <eviction maxEntries="10000" strategy="LRU"/> <expiration maxIdle="100000" wakeUpInterval="5000"/> <lazyDeserialization enabled="true"/> <transaction transactionMode="TRANSACTIONAL" autoCommit="false" lockingMode="OPTIMISTIC"/> </namedCache>
Additionally, the cache is configured programmatically with:
- Flag.ZERO_LOCK_ACQUISITION_TIMEOUT; and
- Flag.FAIL_SILENTLY
The situation is that two threads are concurrently attempting to lock the same key on commit.
- During a JTA transaction, a Hibernate query is executed, and Hibernate places a result in the query cache.
- On commit, the SynchronizationAdaptor creates a PrepareCommand, which contains one or more "modifications", one of which is a PutKeyValueCommand. The SynchronizationAdapter invokes the PrepareCommand.
- When visited, the OptimisticLockingInterceptor loops through the modifications held by the PrepareCommand and visits each one.
- When the PutKeyValueCommand is visited, LockManagerImpl discovers that the key is locked, and throws TimeoutException.
- The Exception is caught by InvocationContextInterceptor, and attempts to find out whether the command it was invoking is affected by Flag.FAIL_SILENTLY. PrepareCommand does not implement FlagAffectedCommand, so this test fails and the Exception is propagated.
It is important to note here that the PutKeyValueCommand does implement FlagAffectedCommand, and does have the Flag.FAIL_SILENTLY flag set. So the problem seems to be that OptimisticLockingInterceptor is unaware that the modifications to the PrepareCommand could throw Exceptions which can be suppressed.
