【发布时间】:2019-07-23 23:22:23
【问题描述】:
当我发出进程启动命令时,Activiti 6.0.0(带有spring boot)保持异步进程并且不会立即启动它: (发出此命令时有一个打开的 JPA 事务,实体作为变量传递给进程)
ProcessInstance processInstance = runtimeService.startProcessInstanceByKey(processId, variableMap);
5 分钟后运行它没有任何错误。
日志:
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.... >
露天线程:Async Job Executor only executes job after lock expiration
【问题讨论】:
-
我对 Activiti 不熟悉,但一种解释是,Activiti 的主线程使用的是常用的每 5 分钟唤醒一次的模式(可能使用
@Scheduled)来检查是否有任何需要运行的东西,而不是立即触发任务。或者它可能正在等待另一个当前正在运行的任务完成,然后再触发您的任务,因为它被配置为顺序执行而不是并行执行。 -
不,没有其他任务,在其他情况下它立即运行,而不是在 0-5 分钟之间的随机超时。对我来说,超时似乎是任务超时,对于长时间运行的任务,假设它已损坏并尝试再次运行,因此 Activiti 似乎认为该任务正在运行,并在 5 分钟后再次尝试。
-
您可以发布您的流程 xml 架构吗?你能在启动过程后确认它真的没有立即启动吗?喜欢
Log.info("Number of process instances: " + runtimeService.createProcessInstanceQuery().count()); -
还有
16:53:14.151 DEBUG [http-nio-8080-exec-2] c.m.i.e.p.input.impl.ImportingPortImpl : Imported a batch, starting workflow...这是什么时候打印的? (在进程启动之前或之后)您是否在启动进程之前执行任何批处理查询? -
@CrazySabbath:之前。是的,在此之前启动时有重新启动事件,这会再次触发一些等待任务以将某些内容加载到运行时业务组件,但这些似乎在单独的事务中更早地正确完成。