我司使用Apache DolphinScheduler作為排程框架很久了,感興趣的小夥伴可以看看這些乾貨文章:
因為之前監控到會出現重複的排程的問題,所以此文記錄排查重複排程問題的全過程,希望對社群其他的小夥伴能夠起到拋磚引玉的作用!
注:本文使用的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。
很多排程框架的底層使用的都是Quartz,比如XXL-Job等。但是日誌這邊確實很清晰的看出來確實Quartz重複觸發了同一個任務。
網上關於Quartz重複排程的問題的解決方案都是加鎖
設定 org.quartz.jobStore.acquireTriggersWithinLock=true
但是DolphinScheduler這邊預設在配置檔案中就已經設定了這個引數。
比較棘手,不太好排查。網上也沒有太多相關的資料。
當時懷疑是不是資料庫的問題,比如鎖失效,多個執行緒拿到了同一把鎖,說實話感覺這個可能性不大,但是確實沒想到其他的可能。
於是就先看Quartz的原始碼和排程邏輯,這種問題一般需要了解更多的底層知識才能發現問題。在看原始碼的時候也看到了這麼一篇部落格,寫的非常清晰,有非常好的參考價值,非常感謝作者。
我們首先講解一下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實現機制。
那說明應該就是這個差別導致了重複排程的問題。
5、問題覆盤
我們假設一種情況,詳見下圖。
兩個伺服器一先一後開啟事務,然後搶佔鎖,拿到鎖後執行排程的邏輯。
如同所示,就出現了重複排程的情況。只看紅框裡面的邏輯,就跟最上面我們模擬在Tidb和Mysql中執行的一樣,伺服器2在Tidb資料庫的情況下,拿到鎖之後讀取的是9.59時間下的Read View,所以也正常觸發了應該10.00排程的任務。出現了重複的排程的情況。甚至可能出現重複排程三次四次的情況,如果在極其巧合的情況下。
三、解決方案
切換Mysql資料庫,或者Tidb資料庫更改到RC隔離級別。
關於為什麼Tidb和Mysql在RR隔離級別下有區別,可以Track
本文由 白鯨開源 提供釋出支援!