Deadlock exceptions

Galen_Hollins · March 30, 2016, 6:36pm

Hi,

I’ve been periodically seeing the errors pasted below when I run my processes. I’m not entirely sure what is generating these, or whether I should be concerned about them. Any feedback would be appreciated concerning this. It looks like the side effect may be that I’m not getting a variable recorded in the database?
I’m using Camunda 7.4.0, and 5.5.40 MySQL Community Server.

Thanks,
Galen

30-Mar-2016 11:12:53.502 SEVERE [pool-2-thread-3] org.camunda.commons.logging.BaseLogger.logError ENGINE-16004 Exception while closing command context: ENGINE-03004 Exception while executing Database Operation 'INSERT VariableInstanceEntity[055f1e9d-f6a3-11e5-b8f7-10bf481b586c]' with message '
### 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.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance-Inline
### The error occurred while setting parameters
### SQL: insert into ACT_RU_VARIABLE     (       ID_,       TYPE_,       NAME_,       PROC_INST_ID_,       EXECUTION_ID_,       CASE_INST_ID_,       CASE_EXECUTION_ID_,       TASK_ID_,       BYTEARRAY_ID_,       DOUBLE_,       LONG_,       TEXT_,       TEXT2_,       VAR_SCOPE_,       SEQUENCE_COUNTER_,       IS_CONCURRENT_LOCAL_,       REV_     )     values (       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       1     )
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction'. Flush summary:
 [
  INSERT HistoricActivityInstanceEventEntity[ServiceTask_5:054e2e97-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[054ef1e8-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9c-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9d-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9e-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9f-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1ea0-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1ea1-f6a3-11e5-b8f7-10bf481b586c]
  INSERT MessageEntity[055f93d2-f6a3-11e5-b8f7-10bf481b586c]
  DELETE MessageEntity[053e76fb-f6a3-11e5-b8f7-10bf481b586c]
  UPDATE ExecutionEntity[053db3a7-f6a3-11e5-b8f7-10bf481b586c]
]
 org.camunda.bpm.engine.ProcessEngineException: ENGINE-03004 Exception while executing Database Operation 'INSERT VariableInstanceEntity[055f1e9d-f6a3-11e5-b8f7-10bf481b586c]' with message '
### 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.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance-Inline
### The error occurred while setting parameters
### SQL: insert into ACT_RU_VARIABLE     (       ID_,       TYPE_,       NAME_,       PROC_INST_ID_,       EXECUTION_ID_,       CASE_INST_ID_,       CASE_EXECUTION_ID_,       TASK_ID_,       BYTEARRAY_ID_,       DOUBLE_,       LONG_,       TEXT_,       TEXT2_,       VAR_SCOPE_,       SEQUENCE_COUNTER_,       IS_CONCURRENT_LOCAL_,       REV_     )     values (       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       1     )
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction'. Flush summary:
 [
  INSERT HistoricActivityInstanceEventEntity[ServiceTask_5:054e2e97-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[054ef1e8-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9c-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9d-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9e-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9f-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1ea0-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1ea1-f6a3-11e5-b8f7-10bf481b586c]
  INSERT MessageEntity[055f93d2-f6a3-11e5-b8f7-10bf481b586c]
  DELETE MessageEntity[053e76fb-f6a3-11e5-b8f7-10bf481b586c]
  UPDATE ExecutionEntity[053db3a7-f6a3-11e5-b8f7-10bf481b586c]
]
	at org.camunda.bpm.engine.impl.db.EnginePersistenceLogger.flushDbOperationException(EnginePersistenceLogger.java:113)
	at org.camunda.bpm.engine.impl.db.entitymanager.DbEntityManager.flushDbOperationManager(DbEntityManager.java:296)
	at org.camunda.bpm.engine.impl.db.entitymanager.DbEntityManager.flush(DbEntityManager.java:282)
	at org.camunda.bpm.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:315)
	at org.camunda.bpm.engine.impl.interceptor.CommandContext.close(CommandContext.java:243)
	at org.camunda.bpm.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:104)
	at org.camunda.bpm.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:30)
	at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobsRunnable.executeJob(ExecuteJobsRunnable.java:79)
	at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:66)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)
Caused by: 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.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance-Inline
### The error occurred while setting parameters
### SQL: insert into ACT_RU_VARIABLE     (       ID_,       TYPE_,       NAME_,       PROC_INST_ID_,       EXECUTION_ID_,       CASE_INST_ID_,       CASE_EXECUTION_ID_,       TASK_ID_,       BYTEARRAY_ID_,       DOUBLE_,       LONG_,       TEXT_,       TEXT2_,       VAR_SCOPE_,       SEQUENCE_COUNTER_,       IS_CONCURRENT_LOCAL_,       REV_     )     values (       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       1     )
### 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:26)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:154)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:141)
	at org.camunda.bpm.engine.impl.db.sql.DbSqlSession.executeInsertEntity(DbSqlSession.java:145)
	at org.camunda.bpm.engine.impl.db.sql.DbSqlSession.insertEntity(DbSqlSession.java:137)
	at org.camunda.bpm.engine.impl.db.AbstractPersistenceSession.executeDbOperation(AbstractPersistenceSession.java:41)
	at org.camunda.bpm.engine.impl.db.entitymanager.DbEntityManager.flushDbOperationManager(DbEntityManager.java:293)
	... 10 more
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:57)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
	at com.mysql.jdbc.Util.getInstance(Util.java:386)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1066)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4190)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4122)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2818)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2157)
	at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1379)
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:44)
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:69)
	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:48)
	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:105)
	at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:71)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:152)
	... 15 more

30-Mar-2016 11:12:53.513 WARNING [pool-2-thread-3] org.camunda.commons.logging.BaseLogger.logWarn ENGINE-14006 Exception while executing job 053e76fb-f6a3-11e5-b8f7-10bf481b586c: org.camunda.bpm.engine.ProcessEngineException: ENGINE-03004 Exception while executing Database Operation 'INSERT VariableInstanceEntity[055f1e9d-f6a3-11e5-b8f7-10bf481b586c]' with message '
### 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.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance-Inline
### The error occurred while setting parameters
### SQL: insert into ACT_RU_VARIABLE     (       ID_,       TYPE_,       NAME_,       PROC_INST_ID_,       EXECUTION_ID_,       CASE_INST_ID_,       CASE_EXECUTION_ID_,       TASK_ID_,       BYTEARRAY_ID_,       DOUBLE_,       LONG_,       TEXT_,       TEXT2_,       VAR_SCOPE_,       SEQUENCE_COUNTER_,       IS_CONCURRENT_LOCAL_,       REV_     )     values (       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       ?,       1     )
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction'. Flush summary:
 [
  INSERT HistoricActivityInstanceEventEntity[ServiceTask_5:054e2e97-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[054ef1e8-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9c-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9d-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9e-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1e9f-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1ea0-f6a3-11e5-b8f7-10bf481b586c]
  INSERT VariableInstanceEntity[055f1ea1-f6a3-11e5-b8f7-10bf481b586c]
  INSERT MessageEntity[055f93d2-f6a3-11e5-b8f7-10bf481b586c]
  DELETE MessageEntity[053e76fb-f6a3-11e5-b8f7-10bf481b586c]
  UPDATE ExecutionEntity[053db3a7-f6a3-11e5-b8f7-10bf481b586c]
]

menski · March 31, 2016, 7:51am

Hi Galen,

can you reproduce this in a test case? Or is it related to a specific process or situation?

Cheers,
Sebastian

Galen_Hollins · April 5, 2016, 12:06am

Hi,

I did some further testing, and I realized that this might be a related bug to:

https://app.camunda.com/jira/browse/CAM-3318

I haven’t put together a test case for this one, but there is a test case attached to that ticket. When I run my code in production (not the test case code), I seem to get the deadlock about 10% of the time. It’s only executing a few processes, so it’s not doing anything crazy. The ticket says “quite unlikely to occur”, which I disagree with, since I see it happening quite often (about 10% of the time). (it this is actually the same bug).

Also, I think this might be happening when I set a variable on the process on a converging parallel gateway, and I’m setting a variable name that already exists. It should just overwrite the variable… I’ll see what happens when I change the name of the variable, but that shouldn’t matter…

Thanks,
Galen

Galen_Hollins · April 5, 2016, 9:13pm

More information about the deadlock below. It appears that and insert into ACT_RU_VARIABLE, and an update of ACT_RU_EXECUTION happen concurrently, and deadlock each other. This is because (I think) of the foreign key linkage (ACT_FK_VAR_BYTEARRAY or ACT_FK_VAR_EXE). I think what the below message is telling me is that the ACT_FK_VAR_BYTEARRAY is locked by both the insert and the update, and they are waiting (deadlocked) on each other to finish. But I could be wrong about this interpretation – these are pretty tricky to interpret

I think what might be going on is that there is a retry that occurs, which might try to update one of the above tables for the same ID?

Thanks,
Galen

Example
Flush summary:
[
INSERT HistoricActivityInstanceEventEntity[ServiceTask_5:80ec12c2-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80ec87f3-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80f47739-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80f4773a-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80f4773b-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80f4773c-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80f4773d-fb6d-11e5-8f23-10bf481b586c]
INSERT VariableInstanceEntity[80f4773e-fb6d-11e5-8f23-10bf481b586c]
INSERT MessageEntity[80f4c560-fb6d-11e5-8f23-10bf481b586c]
DELETE MessageEntity[80d4ba16-fb6d-11e5-8f23-10bf481b586c]
UPDATE ExecutionEntity[80d41dd2-fb6d-11e5-8f23-10bf481b586c]
]

------------------------
LATEST DETECTED DEADLOCK
------------------------
160405 13:32:23
*** (1) TRANSACTION:
TRANSACTION 5D60DAE1, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 6
MySQL thread id 13111, OS thread handle 0x7fbb64107700, query id 4639963387 hostname 137.78.38.93 me update
insert into ACT_RU_VARIABLE
    (
      ID_,
      TYPE_,
      NAME_,
      PROC_INST_ID_,
      EXECUTION_ID_,
      CASE_INST_ID_,
      CASE_EXECUTION_ID_,
      TASK_ID_,
      BYTEARRAY_ID_,
      DOUBLE_,
      LONG_,
      TEXT_,
      TEXT2_,
      VAR_SCOPE_,
      SEQUENCE_COUNTER_,
      IS_CONCURRENT_LOCAL_,
      REV_
    )
    values (
      '80f4773c-fb6d-11e5-8f23-10bf481b586c',
      'string',
      'ServiceTask_5_output',
      '8088e3a7-fb6d-11e5-8f23-10bf481b586c',
      '8088e3a7-fb6d-11e5-8f23-10bf481b586c',
      null,
      null,
      null,
      null,
      null,
      null,
      '',
      null,
      '8088e3a7-fb6d-11e5-8f23-10bf481b586c',
      1,
      0,
      1
    )
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 23204 n bits 248 index `ACT_FK_VAR_BYTEARRAY` of table `devlinux8`.`ACT_RU_VARIABLE` trx id 5D60DAE1 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) TRANSACTION:
TRANSACTION 5D60DB14, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
12 lock struct(s), heap size 3112, 8 row lock(s), undo log entries 4
MySQL thread id 13103, OS thread handle 0x7fbb52274700, query id 4639963392 hostname 137.78.38.93 me Updating
update ACT_RU_EXECUTION set
      REV_ = 5,
      PROC_DEF_ID_ = 'deep_dive_lin_rad:1:87e85253-fb46-11e5-8f23-10bf481b586c',
      ACT_ID_ = null,
      ACT_INST_ID_ = '8088e3a7-fb6d-11e5-8f23-10bf481b586c',
      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_ = 16,
      SEQUENCE_COUNTER_ = 8
    **where ID_ = '8088e3a7-fb6d-11e5-8f23-10bf481b586c'**
      and REV_ = 4
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 23204 n bits 248 index `ACT_FK_VAR_BYTEARRAY` of table `devlinux8`.`ACT_RU_VARIABLE` trx id 5D60DB14 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 282129 n bits 120 index `PRIMARY` of table `devlinux8`.`ACT_RU_EXECUTION` trx id 5D60DB14 lock_mode X locks rec but not gap waiting
Record lock, heap no 45 PHYSICAL RECORD: n_fields 20; compact format; info bits 0
 0: len 30; hex 38303838653361372d666236642d313165352d386632332d313062663438; asc 8088e3a7-fb6d-11e5-8f23-10bf48; (total 36 bytes);
 1: len 6; hex 00005d60dafa; asc   ]`  ;;
 2: len 7; hex 2d000285521418; asc -   R  ;;
 3: len 4; hex 80000004; asc     ;;
 4: len 30; hex 38303838653361372d666236642d313165352d386632332d313062663438; asc 8088e3a7-fb6d-11e5-8f23-10bf48; (total 36 bytes);
 5: len 30; hex 62386434663766372d333635342d346336392d613433372d366635616433; asc b8d4f7f7-3654-4c69-a437-6f5ad3; (total 36 bytes);
 6: SQL NULL;
 7: len 30; hex 646565705f646976655f6c696e5f7261643a313a38376538353235332d66; asc deep_dive_lin_rad:1:87e85253-f; (total 56 bytes);
 8: SQL NULL;
 9: SQL NULL;
 10: SQL NULL;
 11: SQL NULL;
 12: len 30; hex 38303838653361372d666236642d313165352d386632332d313062663438; asc 8088e3a7-fb6d-11e5-8f23-10bf48; (total 36 bytes);
 13: len 1; hex 80; asc  ;;
 14: len 1; hex 80; asc  ;;
 15: len 1; hex 81; asc  ;;
 16: len 1; hex 80; asc  ;;
 17: len 4; hex 80000001; asc     ;;
 18: len 4; hex 80000010; asc     ;;
 19: len 8; hex 8000000000000008; asc         ;;

*** WE ROLL BACK TRANSACTION (1)

Galen_Hollins · April 11, 2016, 11:45pm

Hi,

I’m pretty certain now that this is what causes these deadlocks:

There is a parallel gateway in the process.
Within the parallel gateway there are multiple tasks that set variables (e.g. execution.setVariable) with the SAME NAME.
When the database level statements finally flush out (in a batch?), they lock each other. The ACT_UNIQ_VARIABLE unique key gets violated. Sometimes in my process there are BpmnErrors thrown on the tasks within the parallel gateway, which causes the flush, but I’m not sure yet if this is needed to reproduce. The tasks are running on separate threads (they are asyc, non-exclusive), so this is probably key to reproducing this. As such, they do not know what variable names the other thread are or have set.

The workaround is probably to code up JavaDelagates such that they always prepend some unique identifier to the variable name. This is not a good solution in my opinion…

Sorry, I don’t have time at this moment to submit a test case for this…

Thanks,
Galen