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

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

lucazammarchi Dec 17, 2009 8:41 AM

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

1. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 18, 2009 9:40 AM (in response to lucazammarchi)

Hi,
for your information about my last consideration..jbpm is still running with JBPM_JOB table set to MyISAM engine.

Anyone may let me know why jbpm cause dead-lock events on MySQL when two Timers was inserted in the same time with InnoDB table engine?

Thanks and best regards!

Luca Zammarchi
Actions
2. Re: Could not save Timer - Deadlock found when trying to get lock

kukeltje Dec 18, 2009 10:20 AM (in response to lucazammarchi)

MyISAM has no foreign keys constraints afaik, so it might have something to do with that. Do you have a unit test that demonstrates this behaviour?
Actions
3. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 18, 2009 11:25 AM (in response to kukeltje)
Hi Ronald!
Thanks for your response.

I created two "aggressive" processes with one timer per process e one node that waits 1 seconds before propagates execution.

Attached to this post one zip file with the project containing the two process definition and the Wait.java file.

Starts one instance for each process and signal the two tokens.

In the server.log you'll find the dead lock error.

Let me know if you need more information.

Thank you so much!

Regards

Luca Zammarchi

Crash Test Process.zip 106.0 KB
Actions
4. Re: Could not save Timer - Deadlock found when trying to get lock

kukeltje Dec 18, 2009 1:17 PM (in response to lucazammarchi)

I almost asked for a unitest to demonstrate the issue, but I think that it is not needed. It most likely has nothing to do with the fact that you have 2 processdefinitions (I hope).

You have no wait state in your loop. This means that returning back to the state via the node happens in the same transaction as leaving the state. The timer is not finished then but the engine wants to update it since it enters the node (again) thus wanting to aquire a lock. Since the timer record needs to be updated for finishing the state that is to be left, it is already locked... hence the deadlock.

MyISAM is a way simpler db backend that has no ACID behaviour, so no locks occur but you have no guarantee on consistency.

So You have to change your definition I'm afraid or take the gamble of using MyISAM...

Cheers,

Ronald

Added: http://dev.mysql.com/doc/refman/5.1/en/innodb-record-level-locks.html

Message was edited by: Ronald van Kuijk
1 of 1 people found this helpful
Actions
5. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 21, 2009 6:24 AM (in response to kukeltje)

Hi Ronald,
thanks for support.

I inserted the state in the process with the purpose of the "wait state". And I thought that was the right way..:)

I think that have been the two timer that have created the dead lock, because if you try to run one process instance the dead-lock never occurs.

Is it possibile the problem is in the JobExecutor?

Alternative, how can I insert a "right" wait state?

Thanks and Best Regards

Luca
Actions
6. Re: Could not save Timer - Deadlock found when trying to get lock

kukeltje Dec 21, 2009 11:35 AM (in response to lucazammarchi)

do you have a unit test then to demonstrate the problem?
Actions
7. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 22, 2009 3:21 AM (in response to kukeltje)

Hi Ronald,
may not you use the process in zip file I attached in the last post?

Luca
Actions
8. Re: Could not save Timer - Deadlock found when trying to get lock

kukeltje Dec 22, 2009 8:43 AM (in response to lucazammarchi)

updates to timers are updates for records the jobexcutor uses, so yes they are related.

The reason I ask for a unittest is that I do not want to try and run this through the console. I want to start a java unittest that when run, shows this problem. But, since I'm lazy and it is your problem I was hoping that you could provide one. I personally do not have the time to create a test in the next comming weeks.
Actions
9. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 22, 2009 8:46 AM (in response to kukeltje)

Ok Ronald,
I understand this. So I will create a Unit Test for you.

Thanks again.

Regards

Luca
Actions
10. Re: Could not save Timer - Deadlock found when trying to get lock

mputz Dec 22, 2009 9:01 AM (in response to lucazammarchi)

Luca,
I think that have been the two timer that have created the dead lock, because if you try to run one process instance the dead-lock never occurs.

If you would like jBPM to spawn a need thread, and thus have a new transaction, mark the wait state as 'async="true"'.
Is it possibile the problem is in the JobExecutor?

From the stack trace it seems you are not even using the JobExecutor, but rather the EJB 2 based timer implementation.

Regards,
Martin
Actions
11. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 22, 2009 9:07 AM (in response to mputz)

Hi Martin,
thanks for your response.

I try to set async to true and then I will write response to you.

Yes, I do not use a JobExecutor, I use an EJB in the jbpm-enterprise.jar

Regards.

Luca
Actions
12. Re: Could not save Timer - Deadlock found when trying to get lock

kukeltje Dec 22, 2009 9:31 AM (in response to mputz)

mputz wrote:
Is it possibile the problem is in the JobExecutor?

From the stack trace it seems you are not even using the JobExecutor, but rather the EJB 2 based timer implementation.

Auch... did I miss that... obiously

I think that have been the two timer that have created the dead lock, because if you try to run one process instance the dead-lock never occurs.

If you would like jBPM to spawn a need thread, and thus have a new transaction, mark the wait state as 'async="true"'.

How did you get the impression why he wants a jBPM to spawn a thread. Can you point me to that? Would be a shame if I missed that to.
Actions
13. Re: Could not save Timer - Deadlock found when trying to get lock

mputz Dec 22, 2009 10:06 AM (in response to kukeltje)

How did you get the impression why he wants a jBPM to spawn a thread. Can you point me to that? Would be a shame if I missed that to.

Oops, I should chose my words more carefully. What I meant was that the execution would happen in a different thread in an async node. But more important, in a separate transaction.
Actions
14. Re: Could not save Timer - Deadlock found when trying to get lock

lucazammarchi Dec 22, 2009 10:24 AM (in response to mputz)

So if I set async=true, the timer "going" on one other transaction..

But the process instance execution is waiting for the timer or the token pass to the next node after the timer?
Actions

Go to original post