14 Replies Latest reply on Dec 22, 2009 10:24 AM by Luca Zammarchi

    Could not save Timer - Deadlock found when trying to get lock

    Luca Zammarchi Newbie
      Hi All,

      I am using jboss-4.2.2.GA with jbpm 3.3.1.GA and MySQL 5.0.45 support.

       

      I deployed two BPM process that are polling two tables in two different database instance.

       

      Every process have a timer that leaves to a specific transition after 60 seconds.

       

      For test purpose I changed the "Due Date" to 1 second.

       

      After a random time, jbpm fires an exception when it tries to insert the Timer in the JBPM_JOB table.

       

      Below the jbpm exception and then the dead lock from the InnoDB Monitor in MySQL.

       

      2009-12-17 14:02:18,237 ERROR [org.jbpm.graph.def.GraphElement] action threw exception: could not insert: [org.jbpm.job.Timer]
      org.hibernate.exception.LockAcquisitionException: could not insert: [org.jbpm.job.Timer]
           at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:82)
           at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
           at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:40)
           at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2158)
           at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2638)
           at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:48)
           at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
           at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:298)
           at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:181)
           at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:107)
           at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:187)
           at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:172)
           at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.performSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:94)
           at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:70)
           at org.hibernate.impl.SessionImpl.fireSaveOrUpdate(SessionImpl.java:507)
           at org.hibernate.impl.SessionImpl.saveOrUpdate(SessionImpl.java:499)
           at org.hibernate.impl.SessionImpl.saveOrUpdate(SessionImpl.java:495)
           at org.jbpm.db.JobSession.saveJob(JobSession.java:121)
           at org.jbpm.scheduler.ejbtimer.EntitySchedulerService.createTimer(EntitySchedulerService.java:41)
           at org.jbpm.scheduler.def.CreateTimerAction.execute(CreateTimerAction.java:80)
           at org.jbpm.graph.def.GraphElement.executeAction(GraphElement.java:284)
           at org.jbpm.graph.def.GraphElement.executeActions(GraphElement.java:241)
           at org.jbpm.graph.def.GraphElement.fireAndPropagateEvent(GraphElement.java:213)
           at org.jbpm.graph.def.GraphElement.fireEvent(GraphElement.java:196)
           at org.jbpm.graph.def.Node.enter(Node.java:371)
           at sun.reflect.GeneratedMethodAccessor273.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173)
           at org.jbpm.graph.node.State_$$_javassist_75.enter(State_$$_javassist_75.java)
           at org.jbpm.graph.def.Transition.take(Transition.java:167)
           at org.jbpm.graph.def.Node.leave(Node.java:479)
           at org.jbpm.graph.exe.ExecutionContext.leaveNode(ExecutionContext.java:155)
           at org.jbpm.graph.node.Decision.execute(Decision.java:194)
           at org.jbpm.graph.def.Node.enter(Node.java:390)
           at sun.reflect.GeneratedMethodAccessor273.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173)
           at org.jbpm.graph.def.Node_$$_javassist_81.enter(Node_$$_javassist_81.java)
           at org.jbpm.graph.def.Transition.take(Transition.java:167)
           at org.jbpm.graph.def.Node.leave(Node.java:479)
           at sun.reflect.GeneratedMethodAccessor312.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173)
           at org.jbpm.graph.node.State_$$_javassist_75.leave(State_$$_javassist_75.java)
           at org.jbpm.graph.exe.Token.signal(Token.java:223)
           at org.jbpm.graph.exe.Token.signal(Token.java:180)
           at sun.reflect.GeneratedMethodAccessor326.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173)
           at org.jbpm.graph.exe.Token_$$_javassist_14.signal(Token_$$_javassist_14.java)
           at org.jbpm.job.Timer.execute(Timer.java:87)
           at sun.reflect.GeneratedMethodAccessor321.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173)
           at org.jbpm.job.Timer_$$_javassist_2.execute(Timer_$$_javassist_2.java)
           at org.jbpm.scheduler.ejbtimer.ExecuteTimerCommand.execute(ExecuteTimerCommand.java:27)
           at org.jbpm.ejb.impl.CommandServiceBean.execute(CommandServiceBean.java:147)
           at sun.reflect.GeneratedMethodAccessor315.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.jboss.invocation.Invocation.performCall(Invocation.java:359)
           at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:237)
           at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:158)
           at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:169)
           at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
           at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
           at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
           at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
           at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:168)
           at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
           at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
           at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:648)
           at org.jboss.ejb.Container.invoke(Container.java:960)
           at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:430)
           at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:103)
           at $Proxy80.execute(Unknown Source)
           at org.jbpm.ejb.impl.TimerEntityBean.ejbTimeout(TimerEntityBean.java:143)
           at sun.reflect.GeneratedMethodAccessor319.invoke(Unknown Source)
           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
           at java.lang.reflect.Method.invoke(Method.java:597)
           at org.jboss.invocation.Invocation.performCall(Invocation.java:359)
           at org.jboss.ejb.EntityContainer$ContainerInterceptor.invoke(EntityContainer.java:1187)
           at org.jboss.ejb.plugins.cmp.jdbc.JDBCRelationInterceptor.invoke(JDBCRelationInterceptor.java:87)
           at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:284)
           at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:158)
           at org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:126)
           at org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:278)
           at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:104)
           at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:76)
           at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
           at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
           at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
           at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
           at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:168)
           at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
           at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
           at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:527)
           at org.jboss.ejb.Container.invoke(Container.java:960)
           at org.jboss.ejb.txtimer.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:99)
           at org.jboss.ejb.txtimer.TimerImpl$TimerTaskImpl.run(TimerImpl.java:561)
           at java.util.TimerThread.mainLoop(Timer.java:512)
           at java.util.TimerThread.run(Timer.java:462)
      Caused by: com.mysql.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
           at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:941)
           at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
           at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
           at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
           at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
           at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1332)
           at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1604)
           at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1519)
           at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1504)
           at com.mysql.jdbc.jdbc2.optional.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:840)
           at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
           at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.executeAndExtract(IdentityGenerator.java:73)
           at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:33)
           ... 104 more
      

       

      Dead lock list in the mysql InnoDB Monitor:

       

      ------------------------
      LATEST DETECTED DEADLOCK
      ------------------------
      091217 14:02:18
      *** (1) TRANSACTION:
      TRANSACTION 0 250979, ACTIVE 1 sec, OS thread id 5000 inserting
      mysql tables in use 1, locked 1
      LOCK WAIT 10 lock struct(s), heap size 1024, undo log entries 3
      MySQL thread id 23, query id 78903 localhost 127.0.0.1 root update
      /* insert org.jbpm.job.Timer */ insert into JBPM_JOB (VERSION_, DUEDATE_, PROCESSINSTANCE_, TOKEN_, TASKINSTANCE_, ISSUSPENDED_, ISEXCLUSIVE_, LOCKOWNER_, LOCKTIME_, EXCEPTION_, RETRIES_, NAME_, REPEAT_, TRANSITIONNAME_, ACTION_, GRAPHELEMENTTYPE_, GRAPHELEMENT_, CLASS_) values (0, '2009-12-17 14:02:19', 6, 6, null, 0, 0, null, null, null, 1, 'NessunaModifica_timer', null, 'Riprova', 199, 'org.jbpm.graph.node.State', 225, 'T')
      *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 0 page no 3121 n bits 88 index `IDX_JOB_TOKEN` of table `jbpmdb_331/jbpm_job` trx id 0 250979 lock_mode X locks gap before rec insert intention waiting
      Record lock, heap no 8 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000007; asc         ;; 1: len 8; hex 800000000000020b; asc         ;;
      
      *** (2) TRANSACTION:
      TRANSACTION 0 251028, ACTIVE 0 sec, OS thread id 3188 setting auto-inc lock
      mysql tables in use 1, locked 1
      6 lock struct(s), heap size 1024, undo log entries 2
      MySQL thread id 21, query id 78904 localhost 127.0.0.1 root update
      /* insert org.jbpm.job.Timer */ insert into JBPM_JOB (VERSION_, DUEDATE_, PROCESSINSTANCE_, TOKEN_, TASKINSTANCE_, ISSUSPENDED_, ISEXCLUSIVE_, LOCKOWNER_, LOCKTIME_, EXCEPTION_, RETRIES_, NAME_, REPEAT_, TRANSITIONNAME_, ACTION_, GRAPHELEMENTTYPE_, GRAPHELEMENT_, CLASS_) values (0, '2009-12-17 14:02:19', 7, 7, null, 0, 0, null, null, null, 1, 'timer_attesa', null, 'OK', 213, 'org.jbpm.graph.node.State', 246, 'T')
      *** (2) HOLDS THE LOCK(S):
      RECORD LOCKS space id 0 page no 3121 n bits 88 index `IDX_JOB_TOKEN` of table `jbpmdb_331/jbpm_job` trx id 0 251028 lock_mode X
      Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
       0: len 8; hex 73757072656d756d; asc supremum;;
      
      Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
       0: len 8; hex 8000000000000007; asc         ;; 1: len 8; hex 800000000000020e; asc         ;;
      
      Record lock, heap no 8 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000007; asc         ;; 1: len 8; hex 800000000000020b; asc         ;;
      
      Record lock, heap no 16 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000007; asc         ;; 1: len 8; hex 800000000000020c; asc         ;;
      
      *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
      TABLE LOCK table `jbpmdb_331/jbpm_job` trx id 0 251028 lock mode AUTO-INC waiting
      *** WE ROLL BACK TRANSACTION (2)
      

       

      I don't understand why jbpm incurred a dead-lock exception when insert two timer in the same moment...

       

      I tried to resolve the issue changing engine type of the JBPM_JOB table to MyISAM. Now jbpm seems to work correctly.

       

      Have you any ideas?

       

      thanks to all for any support!

       

      Bye

       

      Luca Zammarchi