【故障排查】10 分钟解决 Quartz 重复调度的疑难杂症

海豚调度 2024-03-20

1342

思科网讯使用Apache DolphinScheduler作为调度框架很久了，感兴趣的小伙伴可以看看我司以前投稿的干货文章：DolphinScheduler×思科网讯：k8S整合实践，提高大数据处理效率！

因为之前监控到会出现重复的调度的问题，所以此文记录排查重复调度问题的全过程，希望对社区其他的小伙伴能够起到抛砖引玉的作用！

注：本文使用的DolphinScheduler 3.1.1的版本。

数据库使用的Tidb数据库，版本6.5.0，数据库的隔离级别是默认的RR（Read Committed）。

Quartz版本为2.3.2，存储模式为JDBC。使用的CronTrigger，设置了org.quartz.jobStore.acquireTriggersWithinLock=true

先说结论。Tidb和Mysql在RR隔离级别下，开启事务后，创建Read view的时机不同，导致Tidb会出现Quartz重复调度的问题。

一、问题发生

前一段时间，客户给我们报了重复调度的问题。

可见下图，同名同调度时间的任务被执行了两次，id相差1。还不是单个偶发情况，基本每一到两天都会出现。对于调度框架，出现重复调度的问题是不可接受的。

二、问题定位

第一步就是定位问题，Apache DolphinScheduler的底层调度框架是Quartz。首先要明确问题的原因，是Quartz的问题还是DolphinScheduler的问题。

通过排查日志，可以看到是Quartz这边的问题。

那问题很明确了，Quartz这边出现了重复调度，当时就觉得很奇怪，因为这个框架非常稳定了，上一次发版本还是在Oct 24, 2019^[1]。

很多调度框架的底层使用的都是Quartz，比如XXL-Job等。但是日志这边确实很清晰的看出来确实Quartz重复触发了同一个任务。

网上关于Quartz重复调度的问题的解决方案都是加锁

设置 org.quartz.jobStore.acquireTriggersWithinLock=true

但是DolphinScheduler这边默认在配置文件中就已经设置了这个参数。比较棘手，不太好排查。网上也没有太多相关的资料。

当时怀疑是不是数据库的问题，比如锁失效，多个线程拿到了同一把锁，说实话感觉这个可能性不大，但是确实没想到其他的可能。

于是就先看Quartz的源码和调度逻辑，这种问题一般需要了解更多的底层知识才能发现问题。在看源码的时候也看到了这么一篇博客^[2]，写的非常清晰，有非常好的参考价值，非常感谢作者。

我们首先讲解一下Quartz里面一些关于调度的概念，后面会用到。

Quartz核心调度主要是QRTZ_TRIGGERS这张表。Quartz把一次调度称之为一次Fire。QRTZ_TRIGGERS这张表里有几个比较核心的字段，TRIGGER_NAME（调度任务名）、PREV_FIRE_TIME（上次调度时间）、NEXT_FIRE_TIME（下次调度时间）、TRIGGER_STATE（当前状态）。
QRTZ_FIRED_TRIGGERS，这张表存储的正在触发的调度信息。

状态正常的Tigger状态变更流程图：

Quartz调度过程简化

加锁
获取将要fire的triggers列表，这里有一个概念，比如当前时间是9.59，他可能会获取下次调度时间为9.57-10.02之间的trrigers，防止漏调度的问题
更新QRTZ_TRIGGERS的状态从WAITING->ACQUAIRED
将trigger信息insert进QRTZ_FIRED_TRIGGERS表，状态为ACQUAIRED
释放锁

等到真正开始调度

加锁
检查QRTZ_TRIGGERS状态是否为ACQUAIRED
如果是，QRTZ_FIRED_TRIGGERS状态更改为EXECUTING
更新QRTZ_TRIGGERS的next_fire_time
将QRTZ_TRIGGERS状态更新为WAITING
释放锁

1、开启MVCC日志

在看源码的同时，也联系DBA是否可以保持DB这边所有的sql以供排查。

DBA这边反馈保持所有的sql会占据大量的磁盘空间，但是可以先开启MVCC日志，也就是可以切换到不同的时间点，去查看当时数据库里面的状态。也很有用。

经过排查可以看见，针对于同一条调度，QRTZ_FIRED_TRIGGERS出现了两条记录，更加印证了重复调度是由于Quartz引起的。

但是拿不到具体执行了哪些sql，单纯看MVCC没有太多的价值。

2、开启全量日志

再次跟DBA沟通后，给我们搭建了一个新集群，仅供测试使用，可以开启全量日志。

有了全量日志就非常方便排查了。

[2024/02/28 18:45:20.141 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251623] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042348020498438] [forUpdateTS=448042348020498438] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="INSERT INTO t_ds_process_instance  ( process_definition_code, process_definition_version, state, state_history, recovery, start_time,  run_times, name, host, command_type, command_param, task_depend_type, max_try_times, failure_strategy, warning_type, warning_group_id, schedule_time, command_start_time,  executor_id, is_sub_process, history_cmd, process_instance_priority, worker_group, environment_code, timeout, tenant_id,  next_process_instance_id, dry_run, restart_time )  VALUES  ( 12316168402080, 1, 1, '[{\"time\":\"2024-02-28 18:45:20\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"init running\"},{\"time\":\"2024-02-28 18:45:20\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"start a new process from scheduler\"}]', 0, '2024-02-28 18:45:20.007',  1, 'shell-1-20240228184520007', 'udp-service-dev-aiad-master-1.udp-service-dev-aiad-master-headless.wap-udp-dev.svc.aiadgen-int-1:5678', 6, '{\"schedule_timezone\":\"Asia/Shanghai\"}', 2, 0, 1, 0, 0, '2024-02-28 18:43:08.0', '2024-02-28 18:45:17.0',  810004, 0, 'SCHEDULER', 2, 'default', -1, 0, -1,  0, 0, '2024-02-28 18:45:20.007' )"]

[2024/02/28 18:45:26.185 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251629] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042349606469635] [forUpdateTS=448042349606469635] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="INSERT INTO t_ds_process_instance  ( process_definition_code, process_definition_version, state, state_history, recovery, start_time,  run_times, name, host, command_type, command_param, task_depend_type, max_try_times, failure_strategy, warning_type, warning_group_id, schedule_time, command_start_time,  executor_id, is_sub_process, history_cmd, process_instance_priority, worker_group, environment_code, timeout, tenant_id,  next_process_instance_id, dry_run, restart_time )  VALUES  ( 12316168402080, 1, 1, '[{\"time\":\"2024-02-28 18:45:26\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"init running\"},{\"time\":\"2024-02-28 18:45:26\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"start a new process from scheduler\"}]', 0, '2024-02-28 18:45:26.05',  1, 'shell-1-20240228184526050', 'udp-service-dev-aiad-master-0.udp-service-dev-aiad-master-headless.wap-udp-dev.svc.aiadgen-int-1:5678', 6, '{\"schedule_timezone\":\"Asia/Shanghai\"}', 2, 0, 1, 0, 0, '2024-02-28 18:43:08.0', '2024-02-28 18:45:24.0',  810004, 0, 'SCHEDULER', 2, 'default', -1, 0, -1,  0, 0, '2024-02-28 18:45:26.05' )"]

通过日志我们可以看到出现了重复调度，预计调度时间是 2024-02-28 18:43:08.0

我们需要找出跟调度相关的日志，QRTZ_FIRED_TRIGGERS和QRTZ_TRIGGERS。

第一次调度相关日志:

[2024/02/28 18:45:08.250 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251625] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042343682015234] [forUpdateTS=448042344638840833] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="UPDATE QRTZ_TRIGGERS SET JOB_NAME = 'job_1201640', JOB_GROUP = 'jobgroup_1200004', DESCRIPTION = null, NEXT_FIRE_TIME = 1709145788000, PREV_FIRE_TIME = 1709145784000, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'CRON', START_TIME = 1709114081000, END_TIME = 4861267200000, CALENDAR_NAME = null, MISFIRE_INSTR = 1, PRIORITY = 5 WHERE SCHED_NAME = 'DolphinScheduler' AND TRIGGER_NAME = 'job_1201640' AND TRIGGER_GROUP = 'jobgroup_1200004'"]

[2024/02/28 18:45:13.348 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251625] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042345307308035] [forUpdateTS=448042345897132034] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="INSERT INTO QRTZ_FIRED_TRIGGERS (SCHED_NAME, ENTRY_ID, TRIGGER_NAME, TRIGGER_GROUP, INSTANCE_NAME, FIRED_TIME, SCHED_TIME, STATE, JOB_NAME, JOB_GROUP, IS_NONCONCURRENT, REQUESTS_RECOVERY, PRIORITY) VALUES('DolphinScheduler', 'udp-service-dev-aiad-master-017091137217721709113723285', 'job_1201640', 'jobgroup_1200004', 'udp-service-dev-aiad-master-01709113721772', 1709145913303, 1709145788000, 'ACQUIRED', null, null, 0, 0, 5)"]

[2024/02/28 18:45:20.141 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251623] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042348020498438] [forUpdateTS=448042348020498438] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="INSERT INTO t_ds_process_instance  ( process_definition_code, process_definition_version, state, state_history, recovery, start_time,  run_times, name, host, command_type, command_param, task_depend_type, max_try_times, failure_strategy, warning_type, warning_group_id, schedule_time, command_start_time,  executor_id, is_sub_process, history_cmd, process_instance_priority, worker_group, environment_code, timeout, tenant_id,  next_process_instance_id, dry_run, restart_time )  VALUES  ( 12316168402080, 1, 1, '[{\"time\":\"2024-02-28 18:45:20\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"init running\"},{\"time\":\"2024-02-28 18:45:20\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"start a new process from scheduler\"}]', 0, '2024-02-28 18:45:20.007',  1, 'shell-1-20240228184520007', 'udp-service-dev-aiad-master-1.udp-service-dev-aiad-master-headless.wap-udp-dev.svc.aiadgen-int-1:5678', 6, '{\"schedule_timezone\":\"Asia/Shanghai\"}', 2, 0, 1, 0, 0, '2024-02-28 18:43:08.0', '2024-02-28 18:45:17.0',  810004, 0, 'SCHEDULER', 2, 'default', -1, 0, -1,  0, 0, '2024-02-28 18:45:20.007' )"]


[2024/02/28 18:45:16.730 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251625] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042346552492033] [forUpdateTS=448042346853957637] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="UPDATE QRTZ_TRIGGERS SET JOB_NAME = 'job_1201640', JOB_GROUP = 'jobgroup_1200004', DESCRIPTION = null, NEXT_FIRE_TIME = 1709145792000, PREV_FIRE_TIME = 1709145788000, TRIGGER_STATE = 'WAITING', TRIGGER_TYPE = 'CRON', START_TIME = 1709114081000, END_TIME = 4861267200000, CALENDAR_NAME = null, MISFIRE_INSTR = 1, PRIORITY = 5 WHERE SCHED_NAME = 'DolphinScheduler' AND TRIGGER_NAME = 'job_1201640' AND TRIGGER_GROUP = 'jobgroup_1200004'"]

第二次调度相关日志:

[2024/02/28 18:45:18.454 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251605] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042345936453636] [forUpdateTS=448042347509317637] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM QRTZ_TRIGGERS WHERE SCHED_NAME = 'DolphinScheduler' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1709145941638 AND (MISFIRE_INSTR = -1 OR (MISFIRE_INSTR != -1 AND NEXT_FIRE_TIME >= 1709145618319)) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC"]

[2024/02/28 18:45:19.281 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251605] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042345936453636] [forUpdateTS=448042347509317637] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="UPDATE QRTZ_TRIGGERS SET TRIGGER_STATE = 'ACQUIRED' WHERE SCHED_NAME = 'DolphinScheduler' AND TRIGGER_NAME = 'job_1201640' AND TRIGGER_GROUP = 'jobgroup_1200004' AND TRIGGER_STATE = 'WAITING'"]

[2024/02/28 18:45:19.497 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251605] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042345936453636] [forUpdateTS=448042347509317637] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="INSERT INTO QRTZ_FIRED_TRIGGERS (SCHED_NAME, ENTRY_ID, TRIGGER_NAME, TRIGGER_GROUP, INSTANCE_NAME, FIRED_TIME, SCHED_TIME, STATE, JOB_NAME, JOB_GROUP, IS_NONCONCURRENT, REQUESTS_RECOVERY, PRIORITY) VALUES('DolphinScheduler', 'udp-service-dev-aiad-master-117091136300541709113631821', 'job_1201640', 'jobgroup_1200004', 'udp-service-dev-aiad-master-11709113630054', 1709145919453, 1709145788000, 'ACQUIRED', null, null, 0, 0, 5)"]

[2024/02/28 18:45:26.185 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251629] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042349606469635] [forUpdateTS=448042349606469635] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="INSERT INTO t_ds_process_instance  ( process_definition_code, process_definition_version, state, state_history, recovery, start_time,  run_times, name, host, command_type, command_param, task_depend_type, max_try_times, failure_strategy, warning_type, warning_group_id, schedule_time, command_start_time,  executor_id, is_sub_process, history_cmd, process_instance_priority, worker_group, environment_code, timeout, tenant_id,  next_process_instance_id, dry_run, restart_time )  VALUES  ( 12316168402080, 1, 1, '[{\"time\":\"2024-02-28 18:45:26\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"init running\"},{\"time\":\"2024-02-28 18:45:26\",\"state\":\"RUNNING_EXECUTION\",\"desc\":\"start a new process from scheduler\"}]', 0, '2024-02-28 18:45:26.05',  1, 'shell-1-20240228184526050', 'udp-service-dev-aiad-master-0.udp-service-dev-aiad-master-headless.wap-udp-dev.svc.aiadgen-int-1:5678', 6, '{\"schedule_timezone\":\"Asia/Shanghai\"}', 2, 0, 1, 0, 0, '2024-02-28 18:43:08.0', '2024-02-28 18:45:24.0',  810004, 0, 'SCHEDULER', 2, 'default', -1, 0, -1,  0, 0, '2024-02-28 18:45:26.05' )"]

可以看出呈现线程关系，也就是第一次调度彻底结束之后，出现了第二次调度。

比较疑惑的点在于第一次调度后已经更新了QRTZ_TRIGGERS的next fire time，但是第二次调度在select 之后触发的调度跟第一次调度的调度时间相同。

我们拿不到sql的执行结果，但是通过日志分析，第二次调度在执行select 获取需要调度的任务时，返回的结果跟第一次调度时返回的结果相同。

非常奇怪。当时怀疑是不是数据库的主从同步有问题，导致第二次调度获取的数据是更新前的数据。

但是通过mvcc查看：

可以明显的看出来，第二次调度的时候，数据库的值更新过的，不存在主从同步的问题。

并且从日志来看，是串行执行的，也就是获取锁没问题，说到获取锁，那么看看加锁释放锁是怎么个流程。

3、查看锁记录

conn可以简单理解为进程号。结果出乎意料，第二次调度的进程在45分11秒就尝试获取锁了，45分18秒才获取到锁。中间等待了7秒。

[2024/02/28 18:45:11.772 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251605] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="SELECT * FROM QRTZ_LOCKS WHERE SCHED_NAME = 'DolphinScheduler' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE"]

[2024/02/28 18:45:18.544 +00:00] [INFO] [session.go:3749] [GENERAL_LOG] [conn=2452605821289251605] [user=udp@10.249.34.78] [schemaVersion=421] [txnStartTS=448042345936453636] [forUpdateTS=448042347509317637] [isReadConsistency=false] [currentDB=udp] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="SET SQL_SELECT_LIMIT=DEFAULT"]

那第一次调度进程什么拿到锁的，于是梳理了一下两个进程申请释放锁的关系。

第一次调度的进程号简称为625，第二次调度的进程号简称为605。

18:45:09.427 625 申请锁

18:45:11.772 605 申请锁 -> 阻塞

18:45:12.210 625 拿到锁

625 执行调度逻辑

625 18:45:16.730 执行完，更新triggers 表

18:45:17.287 625 释放锁

18:45:17.928 625 申请锁

18:45:18.363 605 拿到锁

605 执行调度逻辑

看到这里，就有个猜想，605在拿到锁的时候查询QRTZ_TRIGGERS的结果跟625是相同的。

4、复现问题

那我们可以复现这个流程。

首先创建表。

CREATE TABLE `QRTZ_LOCKS` (
  `SCHED_NAME` varchar(120) NOT NULL,
  `LOCK_NAME` varchar(40) NOT NULL,
  PRIMARY KEY (`SCHED_NAME`,`LOCK_NAME`) 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin;

CREATE TABLE `t_ds_version` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `version` varchar(200) NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `version_UNIQUE` (`version`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin COMMENT='version';

INSERT INTO udp.t_ds_version (version) VALUES
     ('1');

随后开启两个会话，按照如下顺序测试

Tidb

Process1

Process2


start TRANSACTION;
	start TRANSACTION;
SELECT * FROM QRTZ_LOCKS WHERE SCHED_NAME = 'DolphinScheduler' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE; `当前读`
	SELECT * FROM QRTZ_LOCKS WHERE SCHED_NAME = 'DolphinScheduler' AND LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE; `当前读`
UPDATE t_ds_version set `version` = '2' where 1 = 1;
commit;
	select * from t_ds_version; `快照读1
	`version` = 1

Process2的select * from t_ds_version;
读取到的version
=1。

而同样的操作在MySQL上执行时，Process2读取到的却是version
=2。

该问题是因为MySQL和Tidb开启事务时创建Read view的时机不同导致的。

Mysql 在RR隔离级别下，同一个事务中的第一个快照
读才会创建Read View，之后的快照读读取的都是同一个Read View。

没有搜到Tidb对于这块的相关文档，但是通过现象来看则是在开启事务的同时就创建了Read View。关于Mysql的相关文档可以参考MySQL InnoDB的MVCC实现机制^[3]。

那说明应该就是这个差别导致了重复调度的问题。

5、问题复盘

我们假设一种情况，详见下图。

两个服务器一先一后开启事务，然后抢占锁，拿到锁后执行调度的逻辑。

如同所示，就出现了重复调度的情况。只看红框里面的逻辑，就跟最上面我们模拟在Tidb和Mysql中执行的一样，服务器2在Tidb数据库的情况下，拿到锁之后读取的是9.59时间下的Read View，所以也正常触发了应该10.00调度的任务。出现了重复的调度的情况。甚至可能出现重复调度三次四次的情况，如果在极其巧合的情况下。