[jboss-jira] [JBoss JIRA] (WFLY-6498) EJBClient UserTransactions with multiple method invocations generate lock conflicts
Richard Achmatowicz (JIRA)
issues at jboss.org
Fri Apr 8 10:46:01 EDT 2016
[ https://issues.jboss.org/browse/WFLY-6498?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13187861#comment-13187861 ]
Richard Achmatowicz edited comment on WFLY-6498 at 4/8/16 10:45 AM:
--------------------------------------------------------------------
Invocation processing for a method invocation with no UserTransaction (sorry for the degree of detail):
{noformat}
//
// check if a UserTransaction is attached
//
09:53:58,491 INFO [stdout] (default task-8) org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor: Invocation has transaction id: null
//
// create a txn now to wrap the invocation
//
09:53:58,492 INFO [stdout] (default task-8) org.jboss.as.ejb3.tx.CMTTxInterceptor: invokeInOurTx() - create transaction from txn manager:
09:53:58,495 INFO [stdout] (default task-8) org.jboss.as.ejb3.tx.CMTTxInterceptor: got transaction after begin: tx TransactionImple < ac, BasicAction: 0:ffffc0a80067:-1ae21b0:5707b7eb:d status: ActionStatus.RUNNING >
//
// get the SFSB instance
//
09:53:58,496 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor: looking for stateful component instance wih session id: UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]
09:53:58,496 INFO [stdout] (default task-8) org.jboss.as.ejb3.cache.distributable.DistributableCache: get(UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]) - start
//
// create a Batch associated with the get() command *on this specific thread*; this creates a new txn associated with the Batch
//
09:53:58,496 INFO [stdout] (default task-8) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: entering createBatch()
09:53:58,496 INFO [stdout] (default task-8) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: no current batch exists: creating new batch
09:53:58,497 INFO [stdout] (default task-8) org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager: locating bean UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]
09:53:58,500 INFO [stdout] (default task-8) org.jboss.as.ejb3.cache.distributable.DistributableCache: get() - end
//
// got the SFSB instance and saved the Batch in the instance - this is before the invocation gets processed
//
09:53:58,500 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor: invoking instance instance wih session id: UnknownSessionID [575456516765536952684856525656565525349705556525254695649675756]
//
// lock the SFSB instance and set up the Synchronization to call release when finished with the SFSB instance
//
09:53:58,502 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: lock owner (based on active txn or thread) = 0:ffffc0a80067:-1ae21b0:5707b7eb:d
09:53:58,503 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock at 7ecd9234[Unlocked] for stateful component instance: Instance of StatefulIncrementorBean {UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]} during invocation: org.jboss.invocation.InterceptorContext at 7c3ed8f5
09:53:58,503 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock at 7ecd9234[Locked by 0:ffffc0a80067:-1ae21b0:5707b7eb:d] for stateful component instance: Instance of StatefulIncrementorBean {UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]} during invocation: org.jboss.invocation.InterceptorContext at 7c3ed8f5
09:53:58,503 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: using container managed txns - check if we need to register sync
09:53:58,505 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization at 5991637f for tx: 0:ffffc0a80067:-1ae21b0:5707b7eb:d associated with stateful component instance: Instance of StatefulIncrementorBean {UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]}
//
// peform the invocation ...
//
//
// commit the transaction
//
09:53:58,508 INFO [stdout] (default task-8) org.jboss.as.ejb3.tx.CMTTxInterceptor: endTransaction() - committing
//
// fire the Synchronization after transaction commits - this calls release on the instance
//
09:53:58,509 INFO [stdout] (default task-8) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization: calling releaseInstance in afterCompletion()
//
// resume the Batch associated with the instance
//
09:53:58,509 INFO [stdout] (default task-8) org.jboss.as.ejb3.cache.distributable.DistributableCache: release() - start
09:53:58,509 INFO [stdout] (default task-8) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: entering resumeBatch()
09:53:58,510 INFO [stdout] (default task-8) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: existing batch same as resumed
09:53:58,510 INFO [stdout] (default task-8) org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager: locating bean UnknownSessionID [5754565167655369526848565256556565525349705556525254695649675756]
09:53:58,511 INFO [stdout] (default task-8) org.jboss.as.ejb3.cache.distributable.DistributableCache: release() - end
09:53:58,511 INFO [stdout] (default task-8) org.wildfly.clustering.ee.infinispan.InfinispanBatch: closing batch - count = 0
//
// commit the transaction associated with the Batch; we just happen to be on the same thread
//
09:53:58,511 INFO [stdout] (default task-8) org.wildfly.clustering.ee.infinispan.InfinispanBatch: closing batch - commit
{noformat}
was (Author: rachmato):
Invocation processing for a method invocation with no UserTransaction (sorry for the degree of detail):
{noformat}
11:16:07,508 INFO [stdout] (default task-55) org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor: Invocation has transaction id: null
//
// create a txn for this invocation
//
11:16:07,508 INFO [stdout] (default task-55) org.jboss.as.ejb3.tx.CMTTxInterceptor: invokeInOurTx() - create transaction from txn manager:
11:16:07,508 INFO [stdout] (default task-55) org.jboss.as.ejb3.tx.CMTTxInterceptor: got transaction after begin: status = 0
11:16:07,509 INFO [stdout] (default task-55) org.jboss.as.ejb3.tx.CMTTxInterceptor: got transaction after begin: tx TransactionImple < ac, BasicAction: 0:ffffc0a80067:-55fecb13:570527e9:d7 status: ActionStatus.RUNNING >
11:16:07,509 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor: looking for stateful component instance wih session id: UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]
11:16:07,509 INFO [stdout] (default task-55) org.jboss.as.ejb3.cache.distributable.DistributableCache: get(UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]) - start
11:16:07,509 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: entering createBatch()
11:16:07,509 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: no current batch exists: creating new batch
11:16:07,509 INFO [stdout] (default task-55) org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager: locating bean UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]
11:16:07,513 INFO [stdout] (default task-55) org.jboss.as.ejb3.cache.distributable.DistributableCache: get() - end
11:16:07,514 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor: invoking instance instance wih session id: UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]
11:16:07,515 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: lock owner (based on active txn or thread) = 0:ffffc0a80067:-55fecb13:570527e9:d7
11:16:07,516 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock at 2345f95e[Unlocked] for stateful component instance: Instance of StatefulIncrementorBean {UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]} during invocation: org.jboss.invocation.InterceptorContext at c1b214d
11:16:07,516 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock at 2345f95e[Locked by 0:ffffc0a80067:-55fecb13:570527e9:d7] for stateful component instance: Instance of StatefulIncrementorBean {UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]} during invocation: org.jboss.invocation.InterceptorContext at c1b214d
11:16:07,516 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: using container managed txns - check if we need to register sync
11:16:07,517 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor: registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization at 72b2760e for tx: 0:ffffc0a80067:-55fecb13:570527e9:d7 associated with stateful component instance: Instance of StatefulIncrementorBean {UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]}
11:16:07,518 INFO [stdout] (default task-55) org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization: calling releaseInstance in afterCompletion()
//
// txn now completes and calls release
//
11:16:07,518 INFO [stdout] (default task-55) org.jboss.as.ejb3.cache.distributable.DistributableCache: release() - start
11:16:07,519 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: entering resumeBatch()
11:16:07,519 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: existing batch same as resumed
11:16:07,519 INFO [stdout] (default task-55) org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager: locating bean UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166]
11:16:07,523 INFO [stdout] (default task-55) org.jboss.as.ejb3.cache.distributable.DistributableCache: release() - end
11:16:07,523 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatch: closing batch - count = 0
11:16:07,524 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatch: closing batch - commit
11:16:07,541 INFO [stdout] (default task-55) org.jboss.as.ejb3.cache.distributable.DistributableCache: getWeakAffinity() - start
11:16:07,541 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: entering createBatch()
11:16:07,541 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatcher: no current batch exists: creating new batch
11:16:07,542 INFO [stdout] (default task-55) org.jboss.as.ejb3.cache.distributable.DistributableCache: getWeakAffinity() - end
11:16:07,542 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatch: closing batch - count = 0
11:16:07,542 INFO [stdout] (default task-55) org.wildfly.clustering.ee.infinispan.InfinispanBatch: closing batch - commit
Established weak affinity to node-0
{noformat}
> EJBClient UserTransactions with multiple method invocations generate lock conflicts
> ------------------------------------------------------------------------------------
>
> Key: WFLY-6498
> URL: https://issues.jboss.org/browse/WFLY-6498
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Reporter: Richard Achmatowicz
> Assignee: Paul Ferraro
> Fix For: 11.0.0.Alpha1
>
>
> Using the EJBClient library, we should be able to do the following from a standalone EJBClient application:
> // create a UserTransaction associated with a clustered server node X
> // make an invocation on an EJB on X
> // make an invocation on an EJB on X
> // commit the UserTransaction
> However, doing so results in this exception which occurs during processing of the second invocation:
> {noformat}
> [0m[31m11:16:22,580 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-57) ISPN000136: Error executing command GetKeyValueCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UnknownSessionID [4967684957516649565452525270575756545166695455535750486549485166] and requestor GlobalTransaction:<node-0>:120:local. Lock is held by GlobalTransaction:<node-0>:118:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAndRecord(AbstractLockingInterceptor.java:190)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockKey(AbstractTxLockingInterceptor.java:192)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockOrRegisterBackupLock(AbstractTxLockingInterceptor.java:113)
> at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataReadCommand(PessimisticLockingInterceptor.java:70)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:77)
> at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:345)
> at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:330)
> at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
> at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitReadCommand(StateTransferInterceptor.java:176)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitGetKeyValueCommand(StateTransferInterceptor.java:153)
> at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
> at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
> at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:411)
> at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:443)
> at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:286)
> at org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanFactory.findValue(InfinispanBeanFactory.java:87)
> at org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanFactory.findValue(InfinispanBeanFactory.java:49)
> at org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager.findBean(InfinispanBeanManager.java:244)
> at org.jboss.as.ejb3.cache.distributable.DistributableCache.get(DistributableCache.java:124)
> at org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor.processInvocation(StatefulComponentInstanceInterceptor.java:59)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:254)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:333)
> at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:80)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:53)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
> at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:636)
> at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
> at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80)
> at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
> at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
> at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:327)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:67)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:200)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.processMessage(MethodInvocationMessageHandler.java:262)
> at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.processMessage(VersionOneProtocolChannelReceiver.java:213)
> at org.jboss.as.ejb3.remote.protocol.versiontwo.VersionTwoProtocolChannelReceiver.processMessage(VersionTwoProtocolChannelReceiver.java:76)
> at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.handleMessage(VersionOneProtocolChannelReceiver.java:159)
> {noformat}
> The exception does not arise if we perform only one invocation within the UserTransaction.
> This exception is repeatable.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
More information about the jboss-jira
mailing list