cancel
Showing results for 
Search instead for 
Did you mean: 

Deadlock causing transaction corruption and breaking async executor

grahamjohnson80
Champ on-the-rise
Champ on-the-rise
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>
12 REPLIES 12

trademak
Star Contributor
Star Contributor
We are going to release Activiti 5.18 tomorrow or friday.

Best regards,

vanquis
Champ in-the-making
Champ in-the-making
I have experienced some more DB deadlocks while executing UserTasks concurrently (async=true and exclusive=false on tasks, async=true on gateway) testing the current github head Activiti version. I will hold on with more details until the Activiti 5.18 release in case the issues im facing are already fixed there. Error report:
<code>
Exception in thread "1151256610" org.apache.ibatis.exceptions.PersistenceException:
### Error updating database.  Cause: org.h2.jdbc.JdbcSQLException: Wykryto zakleszczenie. Bieżąca transakcja została wycofana. Szczegóły : "
Session #4 (user: SA) on thread pool-1-thread-2 is waiting to lock PUBLIC.ACT_RU_JOB while locking PUBLIC.ACT_RU_EXECUTION (exclusive).
Session #10 (user: SA) on thread 1151256610 is waiting to lock PUBLIC.ACT_RU_EXECUTION while locking PUBLIC.ACT_RU_JOB (exclusive)."
Deadlock detected. The current transaction was rolled back. Details: "
Session #4 (user: SA) on thread pool-1-thread-2 is waiting to lock PUBLIC.ACT_RU_JOB while locking PUBLIC.ACT_RU_EXECUTION (exclusive).
Session #10 (user: SA) on thread 1151256610 is waiting to lock PUBLIC.ACT_RU_EXECUTION while locking PUBLIC.ACT_RU_JOB (exclusive)."; SQL statement:
update ACT_RU_EXECUTION set
      REV_ = ?,
      BUSINESS_KEY_ = ?,
      PROC_DEF_ID_ = ?,
      ACT_ID_ = ?,
      IS_ACTIVE_ = ?,
      IS_CONCURRENT_ = ?,
      IS_SCOPE_ = ?,
      IS_EVENT_SCOPE_ = ?,
      PARENT_ID_ = ?,
      SUPER_EXEC_ = ?,
      SUSPENSION_STATE_ = ?,
      CACHED_ENT_STATE_ = ?,
      NAME_ = ?
    where ID_ = ?
      and REV_ = ? [40001-176]
### The error may involve org.activiti.engine.impl.persistence.entity.ExecutionEntity.updateExecution-Inline
### The error occurred while setting parameters
### SQL: update ACT_RU_EXECUTION set       REV_ = ?,       BUSINESS_KEY_ = ?,       PROC_DEF_ID_ = ?,       ACT_ID_ = ?,       IS_ACTIVE_ = ?,       IS_CONCURRENT_ = ?,       IS_SCOPE_ = ?,       IS_EVENT_SCOPE_ = ?,       PARENT_ID_ = ?,       SUPER_EXEC_ = ?,       SUSPENSION_STATE_ = ?,       CACHED_ENT_STATE_ = ?,       NAME_ = ?     where ID_ = ?       and REV_ = ?
### Cause: org.h2.jdbc.JdbcSQLException: Wykryto zakleszczenie. Bieżąca transakcja została wycofana. Szczegóły : "
Session #4 (user: SA) on thread pool-1-thread-2 is waiting to lock PUBLIC.ACT_RU_JOB while locking PUBLIC.ACT_RU_EXECUTION (exclusive).
Session #10 (user: SA) on thread 1151256610 is waiting to lock PUBLIC.ACT_RU_EXECUTION while locking PUBLIC.ACT_RU_JOB (exclusive)."
Deadlock detected. The current transaction was rolled back. Details: "
Session #4 (user: SA) on thread pool-1-thread-2 is waiting to lock PUBLIC.ACT_RU_JOB while locking PUBLIC.ACT_RU_EXECUTION (exclusive).
Session #10 (user: SA) on thread 1151256610 is waiting to lock PUBLIC.ACT_RU_EXECUTION while locking PUBLIC.ACT_RU_JOB (exclusive)."; SQL statement:
update ACT_RU_EXECUTION set
      REV_ = ?,
      BUSINESS_KEY_ = ?,
      PROC_DEF_ID_ = ?,
      ACT_ID_ = ?,
      IS_ACTIVE_ = ?,
      IS_CONCURRENT_ = ?,
      IS_SCOPE_ = ?,
      IS_EVENT_SCOPE_ = ?,
      PARENT_ID_ = ?,
      SUPER_EXEC_ = ?,
      SUSPENSION_STATE_ = ?,
      CACHED_ENT_STATE_ = ?,
      NAME_ = ?
    where ID_ = ?
      and REV_ = ? [40001-176]
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.flushUpdates(DbSqlSession.java:870)
at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:611)
at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:211)
at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:137)
at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:66)
at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:37)
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.TaskServiceImpl.complete(TaskServiceImpl.java:175)
at TaskCompleter.run(TaskCompleter.java:30)
Caused by: org.h2.jdbc.JdbcSQLException: Wykryto zakleszczenie. Bieżąca transakcja została wycofana. Szczegóły : "
Session #4 (user: SA) on thread pool-1-thread-2 is waiting to lock PUBLIC.ACT_RU_JOB while locking PUBLIC.ACT_RU_EXECUTION (exclusive).
Session #10 (user: SA) on thread 1151256610 is waiting to lock PUBLIC.ACT_RU_EXECUTION while locking PUBLIC.ACT_RU_JOB (exclusive)."
Deadlock detected. The current transaction was rolled back. Details: "
Session #4 (user: SA) on thread pool-1-thread-2 is waiting to lock PUBLIC.ACT_RU_JOB while locking PUBLIC.ACT_RU_EXECUTION (exclusive).
Session #10 (user: SA) on thread 1151256610 is waiting to lock PUBLIC.ACT_RU_EXECUTION while locking PUBLIC.ACT_RU_JOB (exclusive)."; SQL statement:
update ACT_RU_EXECUTION set
      REV_ = ?,
      BUSINESS_KEY_ = ?,
      PROC_DEF_ID_ = ?,
      ACT_ID_ = ?,
      IS_ACTIVE_ = ?,
      IS_CONCURRENT_ = ?,
      IS_SCOPE_ = ?,
      IS_EVENT_SCOPE_ = ?,
      PARENT_ID_ = ?,
      SUPER_EXEC_ = ?,
      SUSPENSION_STATE_ = ?,
      CACHED_ENT_STATE_ = ?,
      NAME_ = ?
    where ID_ = ?
      and REV_ = ? [40001-176]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
at org.h2.message.DbException.get(DbException.java:178)
at org.h2.message.DbException.get(DbException.java:154)
at org.h2.table.RegularTable.doLock(RegularTable.java:518)
at org.h2.table.RegularTable.lock(RegularTable.java:464)
at org.h2.command.dml.Update.update(Update.java:90)
at org.h2.command.CommandContainer.update(CommandContainer.java:79)
at org.h2.command.Command.executeUpdate(Command.java:254)
at org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:199)
at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:55)
at com.sun.proxy.$Proxy3.execute(Unknown Source)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:41)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:66)
at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:45)
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:100)
at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:75)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:148)
… 10 more
</code>

vanquis
Champ in-the-making
Champ in-the-making
I resolved the problem. After switching to the Oracle database deadlocks don't appear any more. However it still doesn't work with the default InMem database. My guess is that h2 locking support is weak and this was the cause.

Regards