0 Replies Latest reply on Mar 11, 2016 1:20 AM by chiaan Hung

    How I deal with mysql Innodb deadlock in my multi-threading application?

    chiaan Hung Novice

      I use perrequest runtimemanager to get kiesession.

         JBPMHelper.setupDataSource();
              EntityManagerFactory emf = Persistence.createEntityManagerFactory("org.jbpm.persistence.jpa");
              RuntimeEnvironmentBuilder builder = RuntimeEnvironmentBuilder.Factory.get()
                      .newClasspathKmoduleDefaultBuilder()
                      .entityManagerFactory(emf)
                      .userGroupCallback(new JBossUserGroupCallbackImpl("classpath:/usergroups.properties"));
              return RuntimeManagerFactory.Factory.get().newPerRequestRuntimeManager(builder.get(), "com.sample:example:1.0");
      
      
      
      

       

      I  get a new RuntimeEngine by runtimemanager and start process in each thread.

      @Override
          public void run() {
      
              System.out.println("Thread0 start");
      
              RuntimeEngine engine = manager.getRuntimeEngine(null);
              KieSession ksession = engine.getKieSession();
              ksession.startProcess("defaultPackage.workFlow", params);
          }
      
      
      
      

       

       

      I use mysql innodb by setting the follwing property.

      in persistence.xml

      <property name="hibernate.dialect" value="org.hibernate.dialect.MySQL5InnoDBDialect"/>
      
      
      
      

       

      in jBPM.properties

      persistence.persistenceunit.dialect=org.hibernate.dialect.MySQL5InnoDBDialect
      
      
      
      

       

      The db schema is created successfully. However, mysql deadlock occurs.

      �T�� 11, 2016 11:20:22 �W�� org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
      WARN: SQL Error: 1213, SQLState: 40001
      �T�� 11, 2016 11:20:22 �W�� org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
      WARN: SQL Error: 1213, SQLState: 40001
      �T�� 11, 2016 11:20:22 �W�� org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
      ERROR: Deadlock found when trying to get lock; try restarting transaction
      �T�� 11, 2016 11:20:22 �W�� org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
      ERROR: Deadlock found when trying to get lock; try restarting transaction
      �T�� 11, 2016 11:20:22 �W�� org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl release
      INFO: HHH000010: On release of batch it still contained JDBC statements
      �T�� 11, 2016 11:20:22 �W�� org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl release
      INFO: HHH000010: On release of batch it still contained JDBC statements
      Exception in thread "pool-3-thread-1" Exception in thread "pool-3-thread-4" java.lang.RuntimeException: Unable to commit transaction
      Thread0 start
          at org.drools.persistence.jta.JtaTransactionManager.commit(JtaTransactionManager.java:239)Thread0 start
      
          at org.drools.persistence.SingleSessionCommandService$TransactionInterceptor.execute(SingleSessionCommandService.java:595)
          at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
          at org.drools.persistence.jpa.OptimisticLockRetryInterceptor.execute(OptimisticLockRetryInterceptor.java:82)
          at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
          at org.drools.persistence.jta.TransactionLockInterceptor.execute(TransactionLockInterceptor.java:73)
          at org.drools.persistence.SingleSessionCommandService.execute(SingleSessionCommandService.java:385)
          at org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession.startProcess(CommandBasedStatefulKnowledgeSession.java:242)
          at org.jbpm.test.MyThread.run(ProcessKModuleMain.java:189)
          at java.lang.Thread.run(Thread.java:745)
          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)
      Caused by: bitronix.tm.internal.BitronixRollbackException: RuntimeException thrown during beforeCompletion cycle caused transaction rollback
          at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:241)
          at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:143)
          at org.drools.persistence.jta.JtaTransactionManager.commit(JtaTransactionManager.java:236)
          ... 12 more
      Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1316)
          at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:999)
          at org.drools.persistence.TriggerUpdateTransactionSynchronization.beforeCompletion(TriggerUpdateTransactionSynchronization.java:76)
          at org.drools.persistence.jta.JtaTransactionSynchronizationAdapter.beforeCompletion(JtaTransactionSynchronizationAdapter.java:54)
          at bitronix.tm.BitronixTransaction.fireBeforeCompletionEvent(BitronixTransaction.java:532)
          at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:235)
          ... 14 more
      Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
          at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:412)
          at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
          at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124)
          at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
          at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:189)
          at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:59)
          at org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(AbstractCollectionPersister.java:1474)
          at org.hibernate.action.internal.CollectionUpdateAction.execute(CollectionUpdateAction.java:86)
          at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:395)
          at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:387)
          at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:308)
          at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:349)
          at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
          at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1195)
          at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:996)
          ... 18 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:62)
          at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
          at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
          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:1065)
          at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4096)
          at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4028)
          at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
          at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
          at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
          at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
          at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2458)
          at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2375)
          at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2359)
          at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:497)
          at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
          at com.sun.proxy.$Proxy39.executeUpdate(Unknown Source)
          at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:186)
          ... 28 more
      java.lang.RuntimeException: Unable to commit transaction
          at org.drools.persistence.jta.JtaTransactionManager.commit(JtaTransactionManager.java:239)
          at org.drools.persistence.SingleSessionCommandService$TransactionInterceptor.execute(SingleSessionCommandService.java:595)
          at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
          at org.drools.persistence.jpa.OptimisticLockRetryInterceptor.execute(OptimisticLockRetryInterceptor.java:82)
          at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41)
          at org.drools.persistence.jta.TransactionLockInterceptor.execute(TransactionLockInterceptor.java:73)
          at org.drools.persistence.SingleSessionCommandService.execute(SingleSessionCommandService.java:385)
          at org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession.startProcess(CommandBasedStatefulKnowledgeSession.java:242)
          at org.jbpm.test.MyThread.run(ProcessKModuleMain.java:189)
          at java.lang.Thread.run(Thread.java:745)
          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)
      Caused by: bitronix.tm.internal.BitronixRollbackException: RuntimeException thrown during beforeCompletion cycle caused transaction rollback
          at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:241)
          at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:143)
          at org.drools.persistence.jta.JtaTransactionManager.commit(JtaTransactionManager.java:236)
          ... 12 more
      Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1316)
          at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:999)
          at org.drools.persistence.TriggerUpdateTransactionSynchronization.beforeCompletion(TriggerUpdateTransactionSynchronization.java:76)
          at org.drools.persistence.jta.JtaTransactionSynchronizationAdapter.beforeCompletion(JtaTransactionSynchronizationAdapter.java:54)
          at bitronix.tm.BitronixTransaction.fireBeforeCompletionEvent(BitronixTransaction.java:532)
          at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:235)
          ... 14 more
      Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
          at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:412)
          at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
          at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124)
          at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
          at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:189)
          at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:59)
          at org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(AbstractCollectionPersister.java:1474)
          at org.hibernate.action.internal.CollectionUpdateAction.execute(CollectionUpdateAction.java:86)
          at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:395)
          at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:387)
          at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:308)
          at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:349)
          at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
          at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1195)
          at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:996)
          ... 18 more
      Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transactionkcontext.getVariable loop1:2
      
      kcontext.getVariable loop1:2    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      
          at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
      kcontext.getVariable loop1:2    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
      
          at java.lang.reflect.Constructor.newInstance(Constructor.java:422)kcontext.getVariable loop2:2
      
          at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
      kcontext.getVariable loop2:2    at com.mysql.jdbc.Util.getInstance(Util.java:386)
      
          at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1065)kcontext.getVariable loop2:2
      
          at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4096)
      kcontext.getVariable duration:0s    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4028)
      
      kcontext.getVariable duration:0s    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
      
      kcontext.getVariable duration:0s    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
      
      t.getName():Janet.getAge():11    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
      
          at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)t.getName():Janet.getAge():11
      
          at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2458)kcontext.getProcessInstance().getId():2190
      
          at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2375)
      t.getName():Janet.getAge():11
          at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2359)
          at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)kcontext.getProcessInstance().getId():2189
      kcontext.getProcessInstance().getId():2191
      
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:497)
          at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
          at com.sun.proxy.$Proxy39.executeUpdate(Unknown Source)
          at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:186)
          ... 28 more
      
      
      
      
      
      
      
      

      The output, I run

      show engine  innodb status;
      
      
      

      in mysql, is shown as follows.

       

      culated from the last 33 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 729 srv_active, 0 srv_shutdown, 41714 srv_idle
      srv_master_thread log flush and writes: 42443
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 5773
      OS WAIT ARRAY INFO: signal count 5582
      Mutex spin waits 11515, rounds 133876, OS waits 3982
      RW-shared spins 1971, rounds 43361, OS waits 1190
      RW-excl spins 7039, rounds 83965, OS waits 432
      Spin rounds per wait: 11.63 mutex, 22.00 RW-shared, 11.93 RW-excl
      
      
      
      
      
      ------------------------
      LATEST DETECTED DEADLOCK
      ------------------------
      2016-03-11 11:20:26 19e8
      *** (1) TRANSACTION:
      TRANSACTION 534150, ACTIVE 0 sec inserting
      mysql tables in use 1, locked 1
      LOCK WAIT 12 lock struct(s), heap size 2936, 10 row lock(s), undo log entries 65
      MySQL thread id 112, OS thread handle 0x1c3c, query id 756476 localhost 127.0.0.1 hca update
      insert into EventTypes (InstanceId, element) values (2488, 'timer')
      *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 4113 page no 4 n bits 80 index `FK_nrecj4617iwxlc65ij6m7lsl1` of table `mydb`.`eventtypes` trx id 534150 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 534152, ACTIVE 0 sec inserting, thread declared inside InnoDB 5000
      mysql tables in use 1, locked 1
      12 lock struct(s), heap size 2936, 10 row lock(s), undo log entries 65
      MySQL thread id 115, OS thread handle 0x19e8, query id 756554 localhost 127.0.0.1 hca update
      insert into EventTypes (InstanceId, element) values (2493, 'timer')
      *** (2) HOLDS THE LOCK(S):
      RECORD LOCKS space id 4113 page no 4 n bits 80 index `FK_nrecj4617iwxlc65ij6m7lsl1` of table `mydb`.`eventtypes` trx id 534152 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 4113 page no 4 n bits 80 index `FK_nrecj4617iwxlc65ij6m7lsl1` of table `mydb`.`eventtypes` trx id 534152 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;;
      
      *** WE ROLL BACK TRANSACTION (2)
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 534501
      Purge done for trx's n:o < 534501 undo n:o < 0 state: running but idle
      History list length 1548
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 0, not started
      MySQL thread id 111, OS thread handle 0x2890, query id 766652 localhost ::1 hca init
      show engine  innodb status
      
      
      
      
      

       

      I use jbpm7.0.0-SNAPSHOT , jdk 1.8, and mysql 5.6.23-log. THX!

      PS. If I get kiesession from singleton runtimemanager, my application runs successfully!

      I change from singleton to perrequest runtimemanager, because I want to run more processes concurrently in one second.

      Is it able to do that?