Activiti Deadlock and Optimistic Exceptions

[archana071]

Hi all,

Problem :

Recently when we started doing load testing we encountered a lot of activiti optimistic exceptions and deadlock exceptions.

Configuration :

• We are using Activiti 5.19 for managing our workflows.
• We have very large running processes which take 6 hours. We have multiple nodes (4) behind our load balancer. We have one job executor per node configured.
• All our processes are activiti:async = true, activiti:exclusive =true.
• We have a lot of call activities nested inside the flows. First flow to Last flow we have around 11 nested flows inside.
• We have many multi instance calls through out the workflow. And we have lot of scenarios where parallel sub process end at the same time. 
• We have Audit level logging - processEngineConfiguration.setHistoryLevel(HistoryLevel.AUDIT);
• So I was wondering if you can suggest us some configuration that we need to do when using multiple nodes to avoid these deadlocks or optimistic exceptions.

Spring process configuration:

processEngineConfiguration.setDataSource(dataSource);
 processEngineConfiguration.setDatabaseSchemaUpdate("true");
 processEngineConfiguration.setHistoryLevel(HistoryLevel.AUDIT);
 processEngineConfiguration.setAsyncExecutorEnabled(true);
 processEngineConfiguration.setAsyncExecutorActivate(true);
 processEngineConfiguration.setFailedJobCommandFactory(new NoRetryFailedJobCommandFactory());
 processEngineConfiguration.setSchemaCommandConfig(new CommandConfig());
// processEngineConfiguration.setAsyncExecutor(getCustomJobExecutor());
 //setting activiti optimistic locking exception retry
 List<CommandInterceptor> listOfInterceptors = new ArrayList<>();
 RetryInterceptor retryInterceptor = new RetryInterceptor();
 retryInterceptor.setNumOfRetries(6);
 retryInterceptor.setWaitTimeInMs(1000);
 retryInterceptor.setWaitIncreaseFactor(5);
 listOfInterceptors.add(retryInterceptor);
 processEngineConfiguration.setCustomPreCommandInterceptors(listOfInterceptors);

Mysql DB Configuration :

db.initialsize: 50,
db.maxactive: 50,
db.maxidle: 15,
db.minidle: 5,
db.maxwait: 10000,
db.minEvictableIdleTimeMillis: 50000,
db.timeBetweenEvictionRunsMillis: 30000,

Exception details :

Optimistic Exception Details :

[pool-2-thread-4] ERROR o.a.e.i.a.ExecuteAsyncRunnable - Job 200444800 failed
org.activiti.engine.ActivitiException: 6 retries failed with ActivitiOptimisticLockingException. Giving up.
at org.activiti.engine.impl.interceptor.RetryInterceptor.execute(RetryInterceptor.java:58) ~[activiti-engine-5.19.0.jar:5.19.0]
at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40) ~[activiti-engine-5.19.0.jar:5.19.0]
at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35) ~[activiti-engine-5.19.0.jar:5.19.0]
at org.activiti.engine.impl.asyncexecutor.ExecuteAsyncRunnable.run(ExecuteAsyncRunnable.java:69) ~[activiti-engine-5.19.0.jar:5.19.0]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_144]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_144]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_144]

Deadlock Exception details :

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.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: 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.flushUpdates(DbSqlSession.java:871)
at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:612)
at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:212)
at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:138)
at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:66)
at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:37)
at org.activiti.engine.impl.interceptor.RetryInterceptor.execute(RetryInterceptor.java:49)
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:69)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.Util.getInstance(Util.java:408)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:951)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2501)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
at sun.reflect.GeneratedMethodAccessor80.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:55)
at com.sun.proxy.$Proxy140.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)
... 16 more

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.HistoricVariableInstanceEntity.updateHistoricVariableInstance-Inline
### The error occurred while setting parameters
### SQL: update ACT_HI_VARINST set REV_ = ?, BYTEARRAY_ID_ = ?, DOUBLE_ = ?, LONG_ = ?, TEXT_ = ?, TEXT2_ = ?, VAR_TYPE_ = ?, LAST_UPDATED_TIME_ = ? where ID_ = ? and REV_ = ?
### 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.flushUpdates(DbSqlSession.java:871)
at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:612)
at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:212)
at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:138)
at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:66)
at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:37)
at org.activiti.engine.impl.interceptor.RetryInterceptor.execute(RetryInterceptor.java:49)
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:69)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.Util.getInstance(Util.java:408)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:951)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2501)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
at sun.reflect.GeneratedMethodAccessor105.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:55)
at com.sun.proxy.$Proxy141.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)
... 16 more

[ryandawson]

I'd be interested in what your async tasks are doing. Are the ones that hit these issues short-lived or long-lived? It would be great if we could put together a reproducer. Apologies that it has been a while (I came across this when looking at another forum thread). Your use-case is certainly of interest (and architecturally sounds like the kind of case we want Activiti 7 to help with).