Multiinstance Subprocess Performance degrades as the number of instances increases

Flowable Engine
1

We are using a multi-instance sub process for our ‘for-each’ loop kind of requirement. Please see below sample bpmn for the same.

'>

 <process id="SimpleLoopForPerformance" name="SimpleLoopForPerformance" isExecutable="true">
<startEvent id="startEvent1" flowable:formFieldValidation="true"></startEvent>
 <serviceTask id="GetRecords1" name="GetRecords1" flowable:delegateExpression="${fetchRecordServiceCall}"></serviceTask>
 <subProcess id="sid-A87F38F2-374D-4E89-889B-938DFB1A4603" name="subProcess"  >
  <multiInstanceLoopCharacteristics isSequential="true" flowable:collection="EmployeeRecords"></multiInstanceLoopCharacteristics>
  <startEvent id="SubProcessStart" flowable:formFieldValidation="true"></startEvent>
   <endEvent id="SubprocessEnd"></endEvent>
   <serviceTask id="PrintRecords" name="PrintRecords" flowable:delegateExpression="${dummyDelegate}"></serviceTask>
   <sequenceFlow id="sid-9AB3C134-DF0C-4C9B-9CEB-A825EFC5C1BB" sourceRef="SubProcessStart" targetRef="PrintRecords"></sequenceFlow>
   <sequenceFlow id="sid-A0C7F764-9492-45E6-AF0B-8DD17DF27BFB" sourceRef="PrintRecords" targetRef="SubprocessEnd"></sequenceFlow>
 </subProcess>
 <endEvent id="sid-DDD4504F-E6EF-44C2-9783-3E9072DE12EB"></endEvent>
 <sequenceFlow id="sid-2F691C36-418C-4C6A-A11A-770E569349A1" sourceRef="sid-A87F38F2-374D-4E89-889B-938DFB1A4603" targetRef="sid-DDD4504F-E6EF-44C2-9783-3E9072DE12EB"></sequenceFlow>
 <sequenceFlow id="sid-4220E4E7-11DC-4A17-BA1F-0C1A8D79207A" sourceRef="GetRecords1" targetRef="sid-A87F38F2-374D-4E89-889B-938DFB1A4603"></sequenceFlow>
 <sequenceFlow id="sid-645E0593-97E3-4696-983D-3375D95624B0" sourceRef="startEvent1" targetRef="GetRecords1"></sequenceFlow>

  1. In Get Records task we are creating dummy records as per configured input and set as process collection variable EmployeeRecords.

  2. Inside the loop I am using a single delegate task -‘DummyDelegate’ which is printing after every 1000 subprocess instance processing.

    int count = (int) execution.getVariable(“loopCounter”);
    if(count % 1000 == 0) {
    LOG.info(“**loopCounter=” + count + " , " + (System.currentTimeMillis()) / 1000);
    }

When we execute the workflow we are getting below log.

2021-02-20 11:13:18.812 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==0 , 1613799798
2021-02-20 11:13:25.168 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==1000 , 1613799805
2021-02-20 11:13:34.187 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==2000 , 1613799814
2021-02-20 11:13:48.058 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==3000 , 1613799828
2021-02-20 11:14:09.013 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==4000 , 1613799849
2021-02-20 11:14:41.461 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==5000 , 1613799881
2021-02-20 11:15:22.205 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==6000 , 1613799922
2021-02-20 11:16:11.106 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==7000 , 1613799971
2021-02-20 11:17:11.337 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==8000 , 1613800031
2021-02-20 11:18:24.506 INFO 2960 — [nio-8999-exec-2] c.s.flowable.delegates.SapperAction : **loopCounter==9000 , 1613800104

As you can see, the execution time per 1000 records is consistently increasing. Many times it is almost 100% increase.
for first 100 records it is 7 sec, next 1000 it is 9, then 14 , 21 , 32 …ad from 8000 to 9000 it is 73 seconds.

We are not sure why this performance degradation.
Any pointers ?

Any suggestions to improve this performance ?

1 Like
2

Split into multiple transactions by adding flowable:async=“true” to “subProcess”

3

Dear Mirek,
Thank you for quick response. I tried with flowable:async=“true” option. It is running the sub processes in different threads and for my basic process (Earlier simple BPMN ) it completed quickly. However when I added a service task after the subprocess , I was getting below error.

2021-03-04 16:59:39 [task-2] ERROR o.f.j.s.i.a.DefaultAsyncRunnableExecutionExceptionHandler - Job e3de06c0-7cdc-11eb-a21d-54e1ad6a5e7d failed
org.flowable.common.engine.api.FlowableOptimisticLockingException: VariableInstanceEntity[id=e3bac760-7cdc-11eb-a21d-54e1ad6a5e7d, name=nrOfActiveInstances, type=integer, longValue=874, textValue=874] was updated by another transaction concurrently

I also tried with flowable:exclusive=“true” , with this I did not get above error but two things happened. The record processing sequence is shuffled (It is expected) and most important is the execution again taking similar time for for higher number of records processing.

2021-03-05 09:17:07 [http-nio-8999-exec-4] INFO c.s.flowable.delegates.SapperAction - ********FetchRecordServiceCall action triggered.
2021-03-05 09:17:16 [http-nio-8999-exec-4] INFO c.s.f.c.SapperFlowableController - *******End startWorkFlow
2021-03-05 09:19:59 [task-17] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=1000 , 1614916199
2021-03-05 09:23:55 [task-21] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=3000 , 1614916435
2021-03-05 09:29:00 [task-21] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=0 , 1614916740
2021-03-05 09:30:14 [task-22] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=8000 , 1614916814
2021-03-05 09:37:11 [task-23] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=10000 , 1614917231
2021-03-05 09:38:01 [task-18] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=7000 , 1614917281
2021-03-05 09:40:55 [task-20] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=2000 , 1614917455
2021-03-05 09:41:52 [task-24] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=4000 , 1614917512
2021-03-05 09:44:28 [task-22] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=6000 , 1614917668
2021-03-05 09:44:29 [task-22] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=9000 , 1614917669
2021-03-05 09:47:46 [task-18] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=5000 , 1614917866.

Is it because the task outside the sub process is becoming the bottleneck ?
Any solution for this. This issue is critical for our project. Please find below updated BPMN for your reference.

’

<documentation>Without Collection only fetch records , Loop with print and out of loop printStatus task</documentation>
<startEvent id="startEvent1" flowable:formFieldValidation="true"></startEvent>
<serviceTask id="GetRecords1" name="GetRecords1" flowable:delegateExpression="${fetchRecordServiceCall}"></serviceTask>
<subProcess id="sid-A87F38F2-374D-4E89-889B-938DFB1A4603" name="subProcess" flowable:async="true" flowable:exclusive="true">
  <multiInstanceLoopCharacteristics isSequential="false" flowable:collection="EmployeeRecords" flowable:elementVariable="employeeRecord"></multiInstanceLoopCharacteristics>
  <startEvent id="SubProcessStart" flowable:formFieldValidation="true"></startEvent>
  <endEvent id="SubprocessEnd"></endEvent>
  <serviceTask id="PrintRecords" name="PrintRecords" flowable:delegateExpression="${dummyDelegate}"></serviceTask>
  <sequenceFlow id="sid-9AB3C134-DF0C-4C9B-9CEB-A825EFC5C1BB" sourceRef="SubProcessStart" targetRef="PrintRecords"></sequenceFlow>
  <sequenceFlow id="sid-F5BCC4E7-ED97-4CA7-9757-D030D26026BF" sourceRef="PrintRecords" targetRef="SubprocessEnd"></sequenceFlow>
</subProcess>
<endEvent id="sid-DDD4504F-E6EF-44C2-9783-3E9072DE12EB"></endEvent>
<sequenceFlow id="sid-4220E4E7-11DC-4A17-BA1F-0C1A8D79207A" sourceRef="GetRecords1" targetRef="sid-A87F38F2-374D-4E89-889B-938DFB1A4603"></sequenceFlow>
<sequenceFlow id="sid-645E0593-97E3-4696-983D-3375D95624B0" sourceRef="startEvent1" targetRef="GetRecords1"></sequenceFlow>
<serviceTask id="PrintStatus" name="PrintStatus" flowable:delegateExpression="${printStatus}"></serviceTask>
<sequenceFlow id="sid-D320A31D-52A6-40A0-A1E0-D39BC3DBF5FA" sourceRef="sid-A87F38F2-374D-4E89-889B-938DFB1A4603" targetRef="PrintStatus"></sequenceFlow>
<sequenceFlow id="sid-533F3EB2-AD9F-4E06-8A23-1816DA63E542" sourceRef="PrintStatus" targetRef="sid-DDD4504F-E6EF-44C2-9783-3E9072DE12EB"></sequenceFlow>
4
  1. When you changed isSequential true->false this provokes “FlowableOptimisticLockingException”
  2. You get FlowableOptimisticLockingException at the end of subprocess so try add flowable:async=“true” to <endEvent id="SubprocessEnd"></endEvent>
5

Dear Mirek,
I tried options as suggested by you. Please find below details.
1. With sequencial multiinstance and Async Subprocess -

  • subProcess id=“sid-A87F38F2-374D-4E89-889B-938DFB1A4603” name=“subProcess” flowable:async=“true” flowable:exclusive=“false”
  • multiInstanceLoopCharacteristics isSequential=“true” flowable:collection=“EmployeeRecords” flowable:elementVariable=“employeeRecord”

We have following result. Overall it is taking approx 20 mins

2021-03-05 15:57:03 [task-1] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=0 , 1614940023
2021-03-05 15:58:12 [task-4] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=1000 , 1614940092
2021-03-05 15:59:24 [task-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=2000 , 1614940164
2021-03-05 16:00:49 [task-4] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=3000 , 1614940249
2021-03-05 16:02:26 [task-6] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=4000 , 1614940346
2021-03-05 16:04:18 [task-4] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=5000 , 1614940458
2021-03-05 16:06:10 [task-8] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=6000 , 1614940570
2021-03-05 16:08:16 [task-7] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=7000 , 1614940696
2021-03-05 16:10:33 [task-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=8000 , 1614940833
2021-03-05 16:13:24 [task-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=9000 , 1614941004
2021-03-05 16:16:19 [task-6] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=10000 , 1614941179
2021-03-05 16:16:19 [task-6] INFO c.s.flowable.delegates.SapperAction - ***execution.getCurrentFlowElement().getName() =PrintStatus

2. In case sequencial multiinstance with Sync subprocess.

  • subProcess id=“sid-A87F38F2-374D-4E89-889B-938DFB1A4603” name=“subProcess” flowable:async=“false” flowable:exclusive=“false”
  • multiInstanceLoopCharacteristics isSequential=“true” flowable:collection=“EmployeeRecords” flowable:elementVariable=“employeeRecord”

We are getting similar performance . i.e. Approx 20 mins

2021-03-08 09:39:02 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - ********FetchRecordServiceCall action triggered.
2021-03-08 09:39:02 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=0 , 1615176542
2021-03-08 09:39:12 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=1000 , 1615176552
2021-03-08 09:39:51 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=2000 , 1615176591
2021-03-08 09:41:06 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=3000 , 1615176666
2021-03-08 09:42:55 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=4000 , 1615176775
2021-03-08 09:44:54 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=5000 , 1615176894
2021-03-08 09:47:58 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=6000 , 1615177078
2021-03-08 09:50:13 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=7000 , 1615177213
2021-03-08 09:52:46 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=8000 , 1615177366
2021-03-08 09:55:37 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=9000 , 1615177537
2021-03-08 09:58:55 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - *********loopCounter=10000 , 1615177735
2021-03-08 09:59:36 [http-nio-8999-exec-2] INFO c.s.flowable.delegates.SapperAction - ***execution.getCurrentFlowElement().getName() =PrintStatus

3. In parallel multiinstance , Async subprocess , exclusive false and added Async flag for end task of subprocess

  • subProcess id=“sid-A87F38F2-374D-4E89-889B-938DFB1A4603” name=“subProcess” flowable:async=“true” flowable:exclusive=“false”>
  • multiInstanceLoopCharacteristics isSequential=“false” flowable:collection=“EmployeeRecords” flowable:elementVariable=“employeeRecord”>
  • endEvent id=“SubprocessEnd” flowable:async=“true”

I was still getting the below error

2021-03-08 11:20:09 [task-3] ERROR o.f.j.s.i.a.DefaultAsyncRunnableExecutionExceptionHandler - Job 1c5b3189-7fd2-11eb-8e46-54e1ad6a5e7d failed
org.flowable.common.engine.api.FlowableOptimisticLockingException: ByteArrayEntity[id=21b4840e-7fd2-11eb-8e46-54e1ad6a5e7d, name=var-CollectedMap, size=24088] was updated by another transaction concurrently

I am trying various combinations and it looks like it is not giving any performance improvement.

6

Ok, lets focus on case “3”. Flowable OptimisticLockingException it’s ok in parallel execution mode, why this bother you… You should set “cfg.setAsyncExecutorNumberOfRetries(3)” on configuration level, and after this exeception Flowable should retry “end element”(this is why we added async on end element) , chcek this, only end should be repeted not serviceTask(which could provide double execution - not wanted)

7

Thank Mirek,
Just wanted to confirm , I am seeing the default value of asyncExecutorNumberOfRetries is already set to 3 (ProcessEngineConfigurationImpl). Is it same configuration ?

protected int asyncExecutorNumberOfRetries = 3

Regards,

8

In the case when there are plenty of jobs running in parallel OptimisticLockinException can cause the problem (when execution is rollbacked 3 times).For such a case BatchService could be helpful.

Regards
Martin

9

Thanks Martin,
I am trying to find the details on how we can use the batch service (other than migration) but couldn’t locate it. Is there any such example / document ? It will really help.

Regards,
Veerendra

10

The only example of usage is migration AFIAK. I used it as a service for purging data for one customer.

Regards
Martin

11

Hi Martin, Mirek,

To improve performance I am planning to split transaction into multiple transactions. eg. After every 1000 (N) records in multiInstanceLoop it should commit the transaction. I was going through flowable properties but unfortunately, I am not able to find any property which can help me to commit the transaction after every N record. Could you please help me if you know any property/configuration to do it? It will really help if you will guide me in the right direction.

Is there any limit on the number of records we can use/process in multiInstanceLoop? I was also going through multiple flowable performance matrix but I am not able to find any performance matrix around multiInstanceLoop.

Regards,
Sachin