ServiceTask executed after process end event

tzar1911 · ‎3 Jan 2017

Hi,

we encountered several cases when serviceTasks are executed after reaching process end event. One example from ACT_HI_ACTINST_TABLE looks like this:

SELECT
   EXECUTION_ID_,
   PROC_INST_ID_,
   ACT_ID_,
   ACT_TYPE_,
   START_TIME_,
   END_TIME_
FROM ACT_HI_ACTINST
  WHERE PROC_INST_ID_ =
   '9841ea77-cee8-11e6-b457-005056aa6e09'
  ORDER BY
    START_TIME_;

9841ea77-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 startevent1 startEvent 2016-12-31 00:35:06 2016-12-31 00:35:06
9841ea77-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 lockOrder serviceTask 2016-12-31 00:35:06 2016-12-31 00:35:06
9841ea77-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 processingOrderStatus serviceTask 2016-12-31 00:35:06 2016-12-31 00:35:06
989cb4b1-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 subprocess1 subProcess 2016-12-31 00:35:06 2016-12-31 00:37:18
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 startevent2 startEvent 2016-12-31 00:35:06 2016-12-31 00:35:06
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 prepareContractContext serviceTask 2016-12-31 00:35:07 2016-12-31 00:35:07
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 processingContractStatus serviceTask 2016-12-31 00:35:08 2016-12-31 00:35:09
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 createSsoAccount serviceTask 2016-12-31 00:35:09 2016-12-31 00:35:09
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 exclusivegateway1 exclusiveGateway 2016-12-31 00:35:09 2016-12-31 00:35:09
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 exclusivegateway2 exclusiveGateway 2016-12-31 00:35:09 2016-12-31 00:35:09
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 modifyParty serviceTask 2016-12-31 00:35:10 2016-12-31 00:35:26
a44b1fb0-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 timerintermediatecatchevent1 intermediateTimer 2016-12-31 00:35:26 2016-12-31 00:37:30
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 createNotification serviceTask 2016-12-31 00:37:17 2016-12-31 00:37:17
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 closedContractStatus serviceTask 2016-12-31 00:37:18 2016-12-31 00:37:18
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 endevent1 endEvent 2016-12-31 00:37:18 2016-12-31 00:37:18
9841ea77-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 registerClosedOrderEvent serviceTask 2016-12-31 00:37:19 2016-12-31 00:37:19
9841ea77-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 closedOrderStatus serviceTask 2016-12-31 00:37:19 2016-12-31 00:37:19
9841ea77-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 endevent2 endEvent 2016-12-31 00:37:19 2016-12-31 00:37:19
989e8977-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 modifyService serviceTask 2016-12-31 00:37:30 2016-12-31 00:37:31
eeec32ad-cee8-11e6-b457-005056aa6e09 9841ea77-cee8-11e6-b457-005056aa6e09 waitingForModifyService intermediateMessageCatch 2016-12-31 00:37:31 2016-12-31 00:37:17

EndEvent2 is process end event and after its completion another task is executed (this modifyService task should be executed right after timerintermediatecatchevent1 and in most cases is).

We are using Activiti only as a processing engine of our Spring application. There are 5 instances of application connected to the same DB.

What can cause such behavior? We are observing it regularly and this is very dangerous for our business processes. As a hint - unordered tasks were executed on different machines.

Also we tuned settings of async executor engine - code snippet with its settings below:

   asyncExecutor.setDefaultAsyncJobAcquireWaitTimeInMillis(1000);
   asyncExecutor.setDefaultTimerJobAcquireWaitTimeInMillis(5 * 1000);
   asyncExecutor.setMaxAsyncJobsDuePerAcquisition(10);
   asyncExecutor.setMaxTimerJobsPerAcquisition(10);
   asyncExecutor.setAsyncJobLockTimeInMillis(10 * 60 * 1000);
   asyncExecutor.setTimerLockTimeInMillis(10 * 60 * 1000);

Activiti version: 5.20.0

Any kind of help or hint would be really appreciated.

gdharley · ‎3 Jan 2017

While I would need a lot more detail (such as queue size, load etc) o provide a direct answer to your question, one wonders why you don't set your "modifyService" to act synchronously if it is to fire immediately after "timerintermediatecatchevent1". If you set it to be synchronous, the timer event will pick up (timers are sitting on the job queue) and immediately (on the same thread) call "modifyService".

Like I said, doesnt answer your question, but you have to be careful about using DB datestamps as the order of insertion may not actually match the order of execution due to transaction boundaries (especialy when you have more than one job scheduler associated with the one db).

Greg

‌

tzar1911 · ‎4 Jan 2017

Hi Greg - thanks for such immediate answer.

When you mentioned "queue size" you think about state of AcquireAsyncJobsDueRunnable thread? I can't give you specific numbers, but this scenario takes place during "rush hours" for our application.

We set modifyService as asynchronous because we want it executed by general thread pool dedicated to async tasks. We don't want to bother "timer thread" to do the task, because sometimes it can take more time (this one is calling some other webservice).

About DB timestamps - we verified logs of applications and it also confirms this strange behavior - task was executed after end event for process.

What information do you need to diagnose the problem in more details? Maybe BPMN definition would be helpful? We are suffering because of this problem, so we want to spot and eliminate it as soon as it possible.

gdharley · ‎4 Jan 2017

Hi Radek,

I'm still a little confused as to why you wont set the modifyService task to synchronous.
By binding it to the same thread as the timer task (which is essentially what synchronous does) you are still using the Job Executor thread pool. Yes, it doesnt use the pool associated with async tasks, but your problem goes away, and, if you are concerned about performance, then separate the nodes that process async and timer tasks. The fact that this happens during "Rush hours" indicates that you need to tune up your job executor.

Another option you have is to "block" the "End event" using a signal receiver that is triggered by a signal send event placed immediately after the modifyService.

Greg

tzar1911 · ‎5 Jan 2017

I attached the screenshot showing process definition. As I said modifyService should be executed right after timer and in most cases is. I don't disagree with your fix proposition but I would like to know what is causing such behavior - is this our fault, or is it engine problem. We also observed this kind of behavior in other processes where serviceTask are located one after the other.

The reason of marking task as async is to make clear transaction boundaries and limit rollback to retry only one task. When we designed process without that, engine was retrying several tasks before faulty one.

tzar1911 · ‎9 Jan 2017

Any hints?