We are incubating activiti 5.16.4 in our dev environment with some regression testing for existed applications and also configured LockFreeJobExecutor implementation in activiti-context. During this process, I am facing a problem with LockfreeJobExecutor in parallel flow.
I am using a 2 way parallel flow implementation in my application. Each flow direction has its own human task and a serviceTask with timer and both are scheduled for same time. When serviceTask start executing, I will get 2 tasks at each parallel flow. To identify corresponding task, I passed taskDefKey as expression field to serviceTask. Here, I am getting taskDefKey expression value same for both service tasks. BTW, with default JobExecutor implementation, both service tasks does their job flawlessly.
Here is the log for the process. You can notice in below log for two job executor threads pool-1-thread-4, pool-1-thread-6.
09-Dec-2014[10:18:53.049]:
EBUG:
ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:38 - ExecutionId : 10e2616a-7fbf-11e4-8f2f-020030001d3c
09-Dec-2014[10:18:53.057]:EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:38 - ExecutionId : 10e324bc-7fbf-11e4-8f2f-020030001d3c
09-Dec-2014[10:18:53.077]:EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:51 - tasks size: 2
09-Dec-2014[10:18:53.078]:EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:62 - taskDefKey Expression value: ParallelTask1
09-Dec-2014[10:18:53.079]:EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:67 - returned taskItem getExpectedtTask: Task[id=0adaa609-7fbf-11e4-8f2f-020030001d3c, name=ParallelTask1]
09-Dec-2014[10:18:53.080]:EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:43 - Task.execId : 0ad88323-7fbf-11e4-8f2f-020030001d3c
09-Dec-2014[10:18:53.084]:EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:51 - tasks size: 2
09-Dec-2014[10:18:53.085]:EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:62 - taskDefKey Expression value: ParallelTask1
09-Dec-2014[10:18:53.086]:EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:67 - returned taskItem getExpectedtTask: Task[id=0adaa609-7fbf-11e4-8f2f-020030001d3c, name=ParallelTask1]
09-Dec-2014[10:18:53.087]:EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:43 - Task.execId : 0ad88323-7fbf-11e4-8f2f-020030001d3c
09-Dec-2014[10:18:53.101]::INFO :ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:82 - -> EscalationServiceTask execute called with taskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c
09-Dec-2014[10:18:53.102]::INFO :ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:87 - -> execute with parentProcessInstId : 0816a3aa-7fbf-11e4-8f2f-020030001d3c parentTaskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c and parentTaskDefinition : ParallelTask1
09-Dec-2014[10:18:53.103]::INFO :ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:82 - -> EscalationServiceTask execute called with taskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c
09-Dec-2014[10:18:53.104]::INFO :ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:87 - -> execute with parentProcessInstId : 0816a3aa-7fbf-11e4-8f2f-020030001d3c parentTaskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c and parentTaskDefinition : ParallelTask1
and later, I am getting OptimisticLockingException as follows for one of the thread. pool-1-thread-6 won the race.
09-Dec-2014[10:18:53.404]::ERROR:ool-1-thread-4:
rg.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable:71 - exception during job execution: HistoricVariableInstanceEntity[id=081d5b0e-7fbf-11e4-8f2f-020030001d3c, name=notificationMessageContent, revision=0, type=string, textValue=blah blah blah] was updated by another transaction concurrently
org.activiti.engine.ActivitiOptimisticLockingException: HistoricVariableInstanceEntity[id=081d5b0e-7fbf-11e4-8f2f-020030001d3c, name=notificationMessageContent, revision=0, type=string, textValue=blah blah blah] was updated by another transaction concurrently
at org.activiti.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:780)
at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:591)
at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:211)
at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:137)
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:131)
at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
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.jobexecutor.ExecuteJobsRunnable.handleSingleJob(ExecuteJobsRunnable.java:69)
at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:52)
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)
I am just wondering that serviceTask expressions are not thread safe it seems while using LockFreeJobExecutor implementation. <b> Is it a bug or any configuration required?? </b>
<bean id="lockFreeJobExecutor" class="org.activiti.engine.impl.jobexecutor.LockFreeJobExecutor">
<property name="queueSize" value="10" />
<property name="corePoolSize" value="10" />
<property name="maxPoolSize" value="50" />
<property name="keepAliveTime" value="5000" />
<property name="jobFetchBatchSize" value="200" />
</bean>
Please suggest me some solution.
Thanks,
Swamy.
I am using a 2 way parallel flow implementation in my application. Each flow direction has its own human task and a serviceTask with timer and both are scheduled for same time. When serviceTask start executing, I will get 2 tasks at each parallel flow. To identify corresponding task, I passed taskDefKey as expression field to serviceTask. Here, I am getting taskDefKey expression value same for both service tasks. BTW, with default JobExecutor implementation, both service tasks does their job flawlessly.
Here is the log for the process. You can notice in below log for two job executor threads pool-1-thread-4, pool-1-thread-6.
09-Dec-2014[10:18:53.049]:
EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:38 - ExecutionId : 10e2616a-7fbf-11e4-8f2f-020030001d3c09-Dec-2014[10:18:53.057]:
EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:38 - ExecutionId : 10e324bc-7fbf-11e4-8f2f-020030001d3c09-Dec-2014[10:18:53.077]:
EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:51 - tasks size: 209-Dec-2014[10:18:53.078]:
EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:62 - taskDefKey Expression value: ParallelTask109-Dec-2014[10:18:53.079]:
EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:67 - returned taskItem getExpectedtTask: Task[id=0adaa609-7fbf-11e4-8f2f-020030001d3c, name=ParallelTask1]09-Dec-2014[10:18:53.080]:
EBUG:ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:43 - Task.execId : 0ad88323-7fbf-11e4-8f2f-020030001d3c09-Dec-2014[10:18:53.084]:
EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:51 - tasks size: 209-Dec-2014[10:18:53.085]:
EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:62 - taskDefKey Expression value: ParallelTask109-Dec-2014[10:18:53.086]:
EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:67 - returned taskItem getExpectedtTask: Task[id=0adaa609-7fbf-11e4-8f2f-020030001d3c, name=ParallelTask1]09-Dec-2014[10:18:53.087]:
EBUG:ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:43 - Task.execId : 0ad88323-7fbf-11e4-8f2f-020030001d3c09-Dec-2014[10:18:53.101]::INFO :
ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:82 - -> EscalationServiceTask execute called with taskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c09-Dec-2014[10:18:53.102]::INFO :
ool-1-thread-6::c.u.n.w.t.e.s.EscalationServiceTask:87 - -> execute with parentProcessInstId : 0816a3aa-7fbf-11e4-8f2f-020030001d3c parentTaskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c and parentTaskDefinition : ParallelTask109-Dec-2014[10:18:53.103]::INFO :
ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:82 - -> EscalationServiceTask execute called with taskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c09-Dec-2014[10:18:53.104]::INFO :
ool-1-thread-4::c.u.n.w.t.e.s.EscalationServiceTask:87 - -> execute with parentProcessInstId : 0816a3aa-7fbf-11e4-8f2f-020030001d3c parentTaskId : 0adaa609-7fbf-11e4-8f2f-020030001d3c and parentTaskDefinition : ParallelTask1and later, I am getting OptimisticLockingException as follows for one of the thread. pool-1-thread-6 won the race.
09-Dec-2014[10:18:53.404]::ERROR:
ool-1-thread-4:rg.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable:71 - exception during job execution: HistoricVariableInstanceEntity[id=081d5b0e-7fbf-11e4-8f2f-020030001d3c, name=notificationMessageContent, revision=0, type=string, textValue=blah blah blah] was updated by another transaction concurrentlyorg.activiti.engine.ActivitiOptimisticLockingException: HistoricVariableInstanceEntity[id=081d5b0e-7fbf-11e4-8f2f-020030001d3c, name=notificationMessageContent, revision=0, type=string, textValue=blah blah blah] was updated by another transaction concurrently
at org.activiti.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:780)
at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:591)
at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:211)
at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:137)
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:131)
at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
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.jobexecutor.ExecuteJobsRunnable.handleSingleJob(ExecuteJobsRunnable.java:69)
at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:52)
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)
I am just wondering that serviceTask expressions are not thread safe it seems while using LockFreeJobExecutor implementation. <b> Is it a bug or any configuration required?? </b>
<bean id="lockFreeJobExecutor" class="org.activiti.engine.impl.jobexecutor.LockFreeJobExecutor">
<property name="queueSize" value="10" />
<property name="corePoolSize" value="10" />
<property name="maxPoolSize" value="50" />
<property name="keepAliveTime" value="5000" />
<property name="jobFetchBatchSize" value="200" />
</bean>
Please suggest me some solution.
Thanks,
Swamy.
