WildFly 8.2 throws Unable to acquire lock after [15 seconds] on key for requestor [GlobalTransaction:<null>:227:local]! Lock held by [GlobalTransaction:<null>:187:local]

[guru.1306]

We are upgrading our application from JBOSS 7.0 to WildFly 8.2.  It's a standalone environment. WildFly 8.2 fails during update of an entity with the below exception.

The infinispan configuration in standalone.xml is shown below.

<subsystem xmlns="urn:jboss:domain:infinispan:2.0">

            <cache-container name="hibernate" default-cache="local-query" module="org.hibernate">

<local-cache name="entity">

                    <transaction mode="NON_XA"/>

                    <eviction strategy="LRU" max-entries="10000"/>

                    <expiration max-idle="100000"/>

                </local-cache>

                <local-cache name="local-query">

                    <transaction mode="NONE"/>

                    <eviction strategy="LRU" max-entries="10000"/>

                    <expiration max-idle="100000"/>

                </local-cache>

                <local-cache name="timestamps">

                    <transaction mode="NONE"/>

                    <eviction strategy="NONE"/>

                </local-cache>

            </cache-container>

        </subsystem>

I have added    <transaction mode="NON_XA"  locking="optimistic"/> but this one fails with write skew trace. It would be of great help if we can get a solution.

Here is a snippet of the stack trace.

Unable to acquire lock after [15 seconds] on key [entityclassName#7cdf9e61-535a-4c98-bd2b-42d576751577] for requestor [GlobalTransaction:<null>:227:local]! Lock held by [GlobalTransaction:<null>:187:local]

  at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:169) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitPutKeyValueCommand(PessimisticLockingInterceptor.java:107) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:186) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:148) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:134) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1306) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.CacheImpl.putInternal(CacheImpl.java:878) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.CacheImpl.put(CacheImpl.java:870) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.DecoratedCache.put(DecoratedCache.java:401) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.infinispan.AbstractDelegatingCache.put(AbstractDelegatingCache.java:276) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

  at org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.update(TransactionalAccessDelegate.java:192) [hibernate-infinispan-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.cache.infinispan.entity.TransactionalAccess.update(TransactionalAccess.java:89) [hibernate-infinispan-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.action.internal.EntityUpdateAction.cacheUpdate(EntityUpdateAction.java:235) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:210) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]

  at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1335) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]

  at org.jboss.as.jpa.container.AbstractEntityManager.flush(AbstractEntityManager.java:457) [wildfly-jpa-8.2.0.Final.jar:8.2.0.Final]

Thanks

Guru

[guru.1306]

I changed the standalone.xml file as shown below. i have added these two attributes and the issue is not reproducible. But in the infinispan doc it says the default is READ_COMMITTED. can somone explain why do we need to explicitly mention it?

   <transaction mode="NON_XA" locking="OPTIMISTIC"/>

<locking isolation="READ_COMMITTED"/> .

<subsystem xmlns="urn:jboss:domain:infinispan:2.0">

            <cache-container name="hibernate" default-cache="local-query" module="org.hibernate">

<local-cache name="entity">

                    <transaction mode="NON_XA" locking="OPTIMISTIC"/>

<locking isolation="READ_COMMITTED"/>

                    <eviction strategy="LRU" max-entries="10000"/>

                    <expiration max-idle="100000"/>

                </local-cache>

                <local-cache name="local-query">

                    <transaction mode="NONE"/>

                    <eviction strategy="LRU" max-entries="10000"/>

                    <expiration max-idle="100000"/>

                </local-cache>

                <local-cache name="timestamps">

                    <transaction mode="NONE"/>

                    <eviction strategy="NONE"/>

                </local-cache>

            </cache-container>

        </subsystem>

[pferraro]

Because this configuration is specific to WildFly - which has it's own default value (i.e. REPEATABLE_READ, in WF8).  This default, however, was changed to READ_COMMITTED for WildFly 9.

[valsaraj007]

I got similar exception in wildfly-8.2 but in domain mode:

Caused by: Unable to acquire lock after [15 seconds] on key [app.entity.UserData#17568183] for requestor [GlobalTransaction:<ltchie-node-00/hibernate>:2482:remote]!

Lock held by [GlobalTransaction:<ltchie-node-00/hibernate>:2135:remote] at org.infinispan.util.concurrent.locks.LockManagerImpl (line 198)

Here is settings:

<cache-container name="hibernate" default-cache="local-query" module="org.hibernate">

                    <transport lock-timeout="120000"/>

                    <local-cache name="local-query">

                        <transaction mode="NONE"/>

                        <eviction strategy="LRU" max-entries="10000"/>

                        <expiration max-idle="100000"/>

                    </local-cache>

                    <invalidation-cache name="entity" mode="SYNC">

                        <transaction mode="NON_XA"/>

                        <eviction strategy="LRU" max-entries="10000"/>

                        <expiration max-idle="100000"/>

                    </invalidation-cache>

                    <replicated-cache name="timestamps" mode="ASYNC">

                        <transaction mode="NONE"/>

                        <eviction strategy="NONE"/>

                    </replicated-cache>

                </cache-container>

I am using XA-DataSource. What change is required to fix this issue?

[tdtappe]

I also get this exception with Wildfly 10.1 in domain mode and the same config as Valsaraj Viswanathan.

If I disable the Cache for a specific entity there is no such exception.

The error occurs if in a first attempt to store the entity the transaction is rolled back due to some exception after the entity was flushed to the entity manager / database. And then in a second attempt (without exception after the flush) I run into this lock exception. So I think it might be related to some transaction stuff. A transaction that is not rolled back (correctly)!?

If the second attempt is started after about 2 minutes after the first attempt with the exception/rollback it works. This is probably because of the expiration timeout of 100.000 ms = 1min 40sec.

Any idea?

--Heiko

[tdtappe]

Oh. I thought I tried it before without success. But obviously I was wrong. Now I am sure: switching the locking type to OPTIMISTIC solves the problem. But is it "allowed" to do so? What are the implications of that?

And to be honest: I don't understand why it solves the problem? Why isn't the cache in the same state after the first exception which should have rolled back all changes made to the cache? Why does it depend on the locking type?

--Heiko

[pferraro]

It seems to me that the issue is with concurrency to the web session.  Trying using the "concurrent" cache configuration from WF10.

[tdtappe]

Hi Paul!

Thanks for pointing that out. But to be honest I don't quite understand what you mean with "try using concurrent cache configuration". Can you elaborate on this and be a little bit more specific? Thanks in advance!

[pferraro]

wildfly/infinispan.xml at 10.1.0.Final · wildfly/wildfly · GitHub

To use, simply set it as the default cache of the web cache-container:

<cache-container name="web" default-cache="concurrent">...</cache-container>

[tdtappe]

Oh, I see!

Unfortunately switching the configuration to "concurrent" doesn't make any difference. I still get "lock exceptions".

[pferraro]

Are you using WildFly 10.1?

[tdtappe]

Yes, I do.

[pferraro]

Please open a separate thread.  This thread relates to an older release.