Activit 6は、非同期プロセスインスタンスを開始する前に5分待機することがあります

Question

Activiti 6.0.0（スプリングブート付き）は非同期プロセスを保持し、プロセス開始コマンド： を発行すると直ちに起動しません（JPAトランザクションこのコマンドを発行し、エンティティが変数としてプロセスに渡される）

ProcessInstance processInstance = runtimeService.startProcessInstanceByKey(processId, variableMap); 

5分後、エラーなしで実行されます。

LOG：

15:17:01.158 DEBUG [http-nio-8080-exec-5] c.m.i.e.p.input.impl.ImportingPortImpl : Starting workflow process... [workflowName=batch-main] 
<5 MINUTE TEA BREAK> 
15:22:10.677 DEBUG [SimpleAsyncTaskExecutor-6] c.m.i.e.i.c.analizers.ContentAnalizers : Task really started.. 

これは、症例の約30％をたまたま他の場合には、それがすぐに開始するので、これは非常に奇妙です。

5分のタイムアウトを待つことなく、すべての場合に直ちにこの問題を解決するには？

詳細なログ：

16:53:14.136 DEBUG [http-nio-8080-exec-2] c.m.i.e.r.a.i.IntellivectorImportAdapter : Getting content stream from multipart [multipartIndex=0;fileName=IMPORTED-4e578b1a-e7f6-4b5a-91d0-9e9a40f3328e.tiff;contentType=image/tiff] 

16:53:14.137 DEBUG [http-nio-8080-exec-2] o.h.e.t.internal.TransactionImpl   : begin 
16:53:14.138 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : select count(RES.ID_) from ACT_RE_PROCDEF RES WHERE RES.KEY_ = 'batch-main' 
16:53:14.142 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : select nextval ('iv_batch_id_seq') 
16:53:14.144 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : select nextval ('iv_document_id_seq') 
16:53:14.147 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into iv_batch (created_date, id) values ('11/28/2017 16:53:14.142', 1245) 
16:53:14.148 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into iv_document (batch_id, created_date, id) values (1245, '11/28/2017 16:53:14.144', 1272) 
16:53:14.150 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into iv_document_contents (mime_type, storage_id, document_id, phase) values ('image/tiff', 'c74d06ef-3c92-4c22-8238-7e45e80d53e3', 1272, 'IMPORTED') 
16:53:14.150 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : update iv_document_contents set index_=0 where document_id=1272 and phase='IMPORTED' 

16:53:14.151 DEBUG [http-nio-8080-exec-2] c.m.i.e.p.input.impl.ImportingPortImpl : Imported a batch, starting workflow... [batchId=1245;documentCount=1;workflowName=batch-main] 
16:53:14.151 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : select * from ACT_RE_PROCDEF where KEY_ = 'batch-main' and (TENANT_ID_ = '' or TENANT_ID_ is null) and VERSION_ = (select max(VERSION_) from ACT_RE_PROCDEF where KEY_ = 'batch-main' and (TENANT_ID_ = '' or TENANT_ID_ is null)) 
16:53:14.153 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into ACT_HI_VARINST (ID_, PROC_INST_ID_, EXECUTION_ID_, TASK_ID_, NAME_, REV_, VAR_TYPE_, BYTEARRAY_ID_, DOUBLE_, LONG_ , TEXT_, TEXT2_, CREATE_TIME_, LAST_UPDATED_TIME_) 
values ('5048', '5047', '5047', NULL, 'batchId', 0, 'long', NULL, NULL, 1245, '1245', NULL, '11/28/2017 16:53:14.153', '11/28/2017 16:53:14.153') 

16:53:14.154 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into ACT_HI_PROCINST (ID_, PROC_INST_ID_, BUSINESS_KEY_, PROC_DEF_ID_, START_TIME_, END_TIME_, DURATION_, START_USER_ID_, START_ACT_ID_, END_ACT_ID_, SUPER_PROCESS_INSTANCE_ID_, DELETE_REASON_, TENANT_ID_, NAME_) 
values ('5047', '5047', NULL, 'batch-main:3:5021', '11/28/2017 16:53:14.152', NULL, NULL, NULL, 'theStart', NULL, NULL, NULL, '', NULL) 
16:53:14.156 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into ACT_RU_EXECUTION (ID_, REV_, PROC_INST_ID_, BUSINESS_KEY_, PROC_DEF_ID_, ACT_ID_, IS_ACTIVE_, IS_CONCURRENT_, IS_SCOPE_,IS_EVENT_SCOPE_, IS_MI_ROOT_, PARENT_ID_, SUPER_EXEC_, ROOT_PROC_INST_ID_, SUSPENSION_STATE_, TENANT_ID_, NAME_, START_TIME_, START_USER_ID_, IS_COUNT_ENABLED_, EVT_SUBSCR_COUNT_, TASK_COUNT_, JOB_COUNT_, TIMER_JOB_COUNT_, SUSP_JOB_COUNT_, DEADLETTER_JOB_COUNT_, VAR_COUNT_, ID_LINK_COUNT_) 
values ('5047', 1, '5047', NULL, 'batch-main:3:5021', NULL, 1, 0, 1, 0, 0, NULL, NULL, '5047', 1, '', NULL, '11/28/2017 16:53:14.152', NULL, 0, 0, 0, 0, 0, 0, 0, 0, 0) , ('5049', 1, '5047', NULL, 'batch-main:3:5021', 'theStart', 1, 0, 0, 0, 0, '5047', NULL, '5047', 1, '', NULL, '11/28/2017 16:53:14.153', NULL, 0, 0, 0, 0, 0, 0, 0, 0, 0) 
16:53:14.157 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into ACT_RU_VARIABLE (ID_, REV_, TYPE_, NAME_, PROC_INST_ID_, EXECUTION_ID_, TASK_ID_, BYTEARRAY_ID_, DOUBLE_, LONG_ , TEXT_, TEXT2_) 
values ('5048', 1, 'long', 'batchId', '5047', '5047', NULL, NULL, NULL, 1245, '1245', NULL) 
16:53:14.159 INFO [http-nio-8080-exec-2] jdbc.sqlonly        : insert into ACT_RU_JOB (ID_, REV_, TYPE_, LOCK_OWNER_, LOCK_EXP_TIME_, EXCLUSIVE_, EXECUTION_ID_, PROCESS_INSTANCE_ID_, PROC_DEF_ID_, RETRIES_, EXCEPTION_STACK_ID_, EXCEPTION_MSG_, DUEDATE_, REPEAT_, HANDLER_TYPE_, HANDLER_CFG_, TENANT_ID_) 
values ('5050', 1, 'message', 'e53309f8-8780-4849-be82-c9acfbffa338', '11/28/2017 16:58:14.153', 1, '5049', '5047', 'batch-main:3:5021', 3, NULL, NULL, NULL, NULL, 'async-continuation', NULL, '') 

    16:53:14.160 DEBUG [http-nio-8080-exec-2] o.h.e.t.internal.TransactionImpl   : begin 
    16:53:14.160 DEBUG [http-nio-8080-exec-2] o.h.e.t.internal.TransactionImpl   : committing 
16:53:14.160 DEBUG [http-nio-8080-exec-2] o.h.e.t.internal.TransactionImpl   : committing 


16:53:14.161 DEBUG [SimpleAsyncTaskExecutor-2] o.h.e.t.internal.TransactionImpl   : begin 
16:53:14.161 INFO [SimpleAsyncTaskExecutor-2] jdbc.sqlonly        : select * from ACT_RU_EXECUTION where ID_ = '5049' 

16:53:14.161 DEBUG [SimpleAsyncTaskExecutor-2] o.h.e.t.internal.TransactionImpl   : committing 
16:53:14.162 DEBUG [SimpleAsyncTaskExecutor-2] o.h.e.t.internal.TransactionImpl   : begin 
16:53:14.162 INFO [SimpleAsyncTaskExecutor-2] jdbc.sqlonly        : select * from ACT_RU_JOB where ID_ = '5050' 

16:53:14.163 DEBUG [SimpleAsyncTaskExecutor-2] o.h.e.t.internal.TransactionImpl   : committing 
16:53:14.163 DEBUG [SimpleAsyncTaskExecutor-2] o.h.e.t.internal.TransactionImpl   : begin 
16:53:14.163 INFO [SimpleAsyncTaskExecutor-2] jdbc.sqlonly        : select * from ACT_RU_EXECUTION where ID_ = '5047' 

16:53:14.164 DEBUG [SimpleAsyncTaskExecutor-2] o.h.e.t.internal.TransactionImpl   : committing 
16:53:22.492 DEBUG [activiti-acquire-async-jobs] o.h.e.t.internal.TransactionImpl   : begin 
16:53:22.493 INFO [activiti-acquire-async-jobs] jdbc.sqlonly        : select RES.* from ACT_RU_JOB RES where LOCK_EXP_TIME_ is null LIMIT 1 OFFSET 0 

16:53:22.493 DEBUG [activiti-acquire-timer-jobs] o.h.e.t.internal.TransactionImpl   : begin 
16:53:22.493 DEBUG [activiti-acquire-async-jobs] o.h.e.t.internal.TransactionImpl   : committing 
16:53:22.493 INFO [activiti-acquire-timer-jobs] jdbc.sqlonly        : select RES.* from ACT_RU_TIMER_JOB RES where DUEDATE_ <= '11/28/2017 16:53:22.493' and LOCK_OWNER_ is null LIMIT 1 OFFSET 0 

16:53:22.495 DEBUG [activiti-acquire-timer-jobs] o.h.e.t.internal.TransactionImpl   : committing 
16:53:22.495 DEBUG [activiti-acquire-timer-jobs] o.h.e.t.internal.TransactionImpl   : begin 
16:53:22.495 DEBUG [activiti-acquire-timer-jobs] o.h.e.t.internal.TransactionImpl   : committing 

<NOT STARTED.... > 

のAlfrescoのスレッド：Async Job Executor only executes job after lock expiration

Answer 1

これは正常な動作です。 Asyncが任意のタスクに対してチェックされると、タスクは他のスレッドから独立して実行できることを意味します。 Activitiは内部的に優先度の高いスレッドが最初に実行されるようにします。したがって、非同期ジョブの実行の遅延。

Answer 2

私はExecuteAsyncJobCmdとのオープントランザクションがこの問題の原因であると考えています。コマンドのコードベースから：

// We need to refetch the job, as it could have been deleted by another concurrent job 
// For exampel: an embedded subprocess with a couple of async tasks and a timer on the boundary of the subprocess 
// when the timer fires, all executions and thus also the jobs inside of the embedded subprocess are destroyed. 
// However, the async task jobs could already have been fetched and put in the queue.... while in reality they have been deleted. 
// A refetch is thus needed here to be sure that it exists for this transaction. 

Job job = commandContext.getJobEntityManager().findById(jobId); 
if (job == null) { 
    log.debug("Job does not exist anymore and will not be executed. It has most likely been deleted " 
     + "as part of another concurrent part of the process instance."); 
    return null; 
} 

これはActiviti春ブーツスターターで提供されているデフォルトのプロセスエンジン設定を使用して、インメモリDBと非同期ジョブのテスト中に、我々が経験している正確な動作です。