AnsweredAssumed Answered

Deadlock causing transaction corruption and breaking async executor

Question asked by grahamjohnson80303 on Jul 10, 2015
Latest reply on Aug 5, 2015 by vanquis
We have just started using Activiti (replacing JBPM 4.4) and we saw a deadlock occur in our test environment that appears to have been caused by on thread trying to lock an ACT_RU_EXECUTION row while another was updating it (unclear if it was locked already).  More troubling, though, this seemed to have left a transaction in a bad state, causing subsequent runs of the async executor to fail with "Transaction is not active" exceptions, and this did not go away until we restarted JBoss.  The same thing happened two more times later.  See below for all the information I can provide; the one thing that is missing is an stack trace or other indication of what code was performing the ACT_RU_EXECUTION update in the second transaction involved in the deadlock.

What might cause this deadlock?  Is it an Activiti bug?  A configuration problem (Activiti, data source, transactions, iBatis, JBoss, MySQL)?  An application bug (i.e. we are misusing Activiti somehow)?  Is there any way to further diagnore or prevent the deadlock?  Is there any way to further diagnore or prevent the transaction being messed up by the deadlock?


Here is the first exception about the deadlock:


2015-07-09 23:41:09,241 ERROR [pl.interceptor.JtaTransactionInterceptor] (    pool-14-thread-1) {     } Error when rolling back transaction, orginal exception was:
org.apache.ibatis.exceptions.PersistenceException:
### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
### The error may involve org.activiti.engine.impl.persistence.entity.ExecutionEntity.clearProcessInstanceLockTime-Inline
### The error occurred while setting parameters
### SQL: update ACT_RU_EXECUTION      set       LOCK_TIME_ = null     where ID_ = ?
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
        at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:23)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:150)
        at org.activiti.engine.impl.db.DbSqlSession.update(DbSqlSession.java:180)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntityManager.clearProcessInstanceLockTime(ExecutionEntityManager.java:212)
        at org.activiti.engine.impl.cmd.UnlockExclusiveJobCmd.execute(UnlockExclusiveJobCmd.java:55)
        at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
        at org.activiti.engine.impl.interceptor.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:65)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
        at org.activiti.engine.impl.asyncexecutor.ExecuteAsyncRunnable.run(ExecuteAsyncRunnable.java:97)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)


Here is the SHOW ENGINE INNODB STATUS output:


————————
LATEST DETECTED DEADLOCK
————————
150709 20:28:08
*** (1) TRANSACTION:
TRANSACTION CCB4FB3, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 15308, OS thread handle 0x7fb7c709e700, query id 17739169 127.0.0.1 root Updating
update ACT_RU_EXECUTION
    set
      LOCK_TIME_ = null
    where ID_ = '73837'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 116736 n bits 152 index `PRIMARY` of table `SCActiviti`.`ACT_RU_EXECUTION` trx id CCB4FB3 lock_mode X locks rec but not gap waiting
Record lock, heap no 83 PHYSICAL RECORD: n_fields 19; compact format; info bits 0
[record info omitted]

*** (2) TRANSACTION:
TRANSACTION CCB4FB1, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
12 lock struct(s), heap size 1248, 6 row lock(s), undo log entries 14
MySQL thread id 15317, OS thread handle 0x7fb7c7ac6700, query id 17739179 127.0.0.1 root Updating
update ACT_RU_EXECUTION set
      REV_ = 18,
      BUSINESS_KEY_ = '[value omitted]',
      PROC_DEF_ID_ = '[value omitted]:2:67630',
      ACT_ID_ = null,
      IS_ACTIVE_ = 0,
      IS_CONCURRENT_ = 0,
      IS_SCOPE_ = 1,
      IS_EVENT_SCOPE_ = 0,
      PARENT_ID_ = null,
      SUPER_EXEC_ = null,
      SUSPENSION_STATE_ = 1,
      CACHED_ENT_STATE_ = 4,
      NAME_ = null,
      LOCK_TIME_ = null
    where ID_ = '73837'
      and REV_ = 17
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 116736 n bits 152 index `PRIMARY` of table `SCActiviti`.`ACT_RU_EXECUTION` trx id CCB4FB1 lock mode S locks rec but not gap
Record lock, heap no 83 PHYSICAL RECORD: n_fields 19; compact format; info bits 0
[record info omitted]

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 116736 n bits 152 index `PRIMARY` of table `SCActiviti`.`ACT_RU_EXECUTION` trx id CCB4FB1 lock_mode X locks rec but not gap waiting
[record info omitted]

*** WE ROLL BACK TRANSACTION (1)


Then we got this exception, which is presumably related to the transaction being put in a bad state:


2015-07-09 23:41:10,318 ERROR [.impl.asyncexecutor.ExecuteAsyncRunnable] (    pool-14-thread-1) {     } Error while unlocking exclusive job 75713
java.lang.IllegalMonitorStateException
        at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:151)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261)
        at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457)
        at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.unlock(BaseWrapperManagedConnection.java:277)
        at org.jboss.resource.adapter.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:268)
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:396)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3270)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3248)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1933)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:114)
        at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:201)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1497)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:165)
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:114)
        at org.activiti.engine.impl.interceptor.JtaTransactionInterceptor.doRollback(JtaTransactionInterceptor.java:147)
        at org.activiti.engine.impl.interceptor.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:67)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
        at org.activiti.engine.impl.asyncexecutor.ExecuteAsyncRunnable.run(ExecuteAsyncRunnable.java:97)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)


Subsequent async executor runs then (all?) got the following exception:


2015-07-09 23:41:15,949 ERROR [.impl.asyncexecutor.ExecuteAsyncRunnable] (    pool-14-thread-1) {     } Error while locking exclusive job 75738
org.apache.ibatis.exceptions.PersistenceException:
### Error querying database.  Cause: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 323983b3:8222:559eee8e:9444 status: ActionStatus.ABORTING >; - nested throwable: (javax.resource.Reso
urceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 323983b3:8222:559eee8e:9444 status: ActionStatus.ABORTING >)
### The error may exist in org/activiti/db/mapping/entity/Execution.xml
### The error may involve org.activiti.engine.impl.persistence.entity.ExecutionEntity.selectExecution
### The error occurred while executing a query
### Cause: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 323983b3:8222:559eee8e:9444 status: ActionStatus.ABORTING >; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 323983b3:8222:559eee8e:9444 status: ActionStatus.ABORTING >)
        at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:23)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:107)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:98)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:62)
        at org.activiti.engine.impl.db.DbSqlSession.selectById(DbSqlSession.java:457)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntityManager.findExecutionById(ExecutionEntityManager.java:108)
        at org.activiti.engine.impl.cmd.LockExclusiveJobCmd.execute(LockExclusiveJobCmd.java:53)
        at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
        at org.activiti.engine.impl.interceptor.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:65)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
        at org.activiti.engine.impl.asyncexecutor.ExecuteAsyncRunnable.run(ExecuteAsyncRunnable.java:52)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

       
Here is how the data source is configured in JBoss 5.1:


<?xml version="1.0" encoding="UTF-8"?>
<datasources>
   <xa-datasource>
      <jndi-name>SCActivitiDS</jndi-name>
      <xa-datasource-class>com.mysql.jdbc.jdbc2.optional.MysqlXADataSource</xa-datasource-class>
      <xa-datasource-property name="URL">[value omitted]</xa-datasource-property>
      <user-name>[value omitted]</user-name>
      <password>[value omitted]</password>
      <max-pool-size>100</max-pool-size>
      <track-connection-by-tx>true</track-connection-by-tx>
      <metadata>
         <type-mapping>mySQL</type-mapping>
      </metadata>
   </xa-datasource>
</datasources>


Here is our activiti.cfg.xml:


<beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd">

   <bean id="processEngineConfiguration" class="org.activiti.engine.impl.cfg.JtaProcessEngineConfiguration">
      <property name="dataSource" ref="dataSource" />
      <property name="databaseSchemaUpdate" value="false" />
      <property name="transactionManager" ref="transactionManager" />
      <property name="asyncExecutorEnabled" value="true" />
      <property name="asyncExecutorActivate" value="true" />
   </bean>

   <bean id="dataSource" class="org.springframework.jndi.JndiObjectFactoryBean">
      <property name="jndiName" value="java:SCActivitiDS" />
   </bean>

   <bean id="transactionManager" class="org.springframework.jndi.JndiObjectFactoryBean">
      <property name="jndiName" value="java:/TransactionManager" />
   </bean>

</beans>

Outcomes