最近，线上运行的定时任务出现调度失败。调整了相关参数后，虽然遏制了调度失败的情况，却导致任务调度的延迟极度增加。同时还观察到，在多机部署的环境中，负载极不均匀，于是深入代码排查一番。
Table of Contents
TL; DR
- 不要使用 Spring 提供的
org.springframework.scheduling.quartz.SchedulerFactoryBean#setTaskExecutor方法自定义工作线程池 - 要注意 Spring 与 Quartz 的部分配置默认值不一致，如
org.quartz.threadPool.class - 一般情况下使用 Quartz 提供的
SimpleThreadPool配合参数org.quartz.threadPool.threadCount调整最大线程数即可 - 如果需要自定义工作线程池，则必须直接实现
org.quartz.spi.ThreadPool接口，并一定要实现blockForAvailableThreads方法，支持阻塞等待 - 适当设置
org.quartz.scheduler.batchTriggerAcquisitionMaxCount参数，使用批量能力降低 DB 交互带来的延迟
任务调度失败
问题现象
接用户反馈，一个一直正常运行的定时任务，在确认没有进行任何变动的情况下，却突然不再被调度了。经过确认，确实没有找到该任务的任何改动痕迹。因此怀疑问题是出在 Quartz 调度引擎上。
找出原因
看到这个现象，第一反应是 Quartz 里的 Trigger 异常了。因为 Quartz 对于所有状态是异常的 Trigger 都不会再次调度，表现为没有任何操作但是任务不执行。于是查看 QRTZ_TRIGGERS 表，筛选过后果然看到了 STATE 为 ERROR 的 TRIGGER。根据 TRIGGER_NAME 和 TRIGGER_GROUP 确定为用户反馈的任务所对应的触发器。
确定了问题是 TRIGGER_STATE 后，就要找到状态变化的点。先查看出现问题时的业务日志，可以看到有这样的记录穿插其中：
[2021-04-16 16:14:08.001][|][quartz-scheduler_QuartzSchedulerThread] ERROR o.s.s.q.LocalTaskExecutorThreadPool:runInThread:84 - Task has been rejected by TaskExecutor
org.springframework.core.task.TaskRejectedException: Executor [java.util.concurrent.ThreadPoolExecutor@ef3310e[Running, pool size = 50, active threads = 50, queued tasks = 100, completed tasks = 20]] did not accept task: org.quartz.core.JobRunShell@5841bfb6
at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:324)
at org.springframework.scheduling.quartz.LocalTaskExecutorThreadPool.runInThread(LocalTaskExecutorThreadPool.java:80)
at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:398)
Caused by: java.util.concurrent.RejectedExecutionException: Task org.quartz.core.JobRunShell@5841bfb6 rejected from java.util.concurrent.ThreadPoolExecutor@ef3310e[Running, pool size = 50, active threads = 50, queued tasks = 100, completed tasks = 20]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:321)
… 2 common frames omitted
[2021-04-16 16:14:08.001][|][quartz-scheduler_QuartzSchedulerThread] ERROR o.quartz.core.QuartzSchedulerThread:run:403 - ThreadPool.runInThread() return false!从日志里可以看到，有一些定时任务被线程池拒绝了。而我们的线程池中有 50 个工作线程，100 个等待队列。也就是说这台机器短时间内承担了 150 个以上的调度任务，就会导致线程池无法承受如此多的任务而导致后续的任务被拒绝执行。因此猜测这部分被拒绝执行的任务导致了 Quartz 的 Trigger 状态异常。
于是查找相关代码，可以看到有一共有四处修改状态为 ERROR 的代码。其中由于 retrieveJob 导致的错误暂时排除，因为 DB 中 Trigger 的数据都是高度相似的。如果是这里出了问题，那么一定是大批量的出现错误，而非个别任务。继续查找，找到如下逻辑：
JobRunShell shell = null;
try {
// 创建触发器执行环境
shell = qsRsrcs.getJobRunShellFactory().createJobRunShell(bndle);
shell.initialize(qs);
} catch (SchedulerException se) {
qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), Trigger.CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
continue;
}
// 提交执行并检查提交结果
if (qsRsrcs.getThreadPool().runInThread(shell) == false) {
// this case should never happen, as it is indicative of the
// scheduler being shutdown or a bug in the thread pool or
// a thread pool being used concurrently - which the docs
// say not to do...
getLog().error("ThreadPool.runInThread() return false!");
qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), Trigger.CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
}从这里可以看到，如果任务提交到线程池的时候失败了，那么就会导致任务被标记为 ERROR。而这刚好符合我们看到的日志现象。由于线程池等待队列满导致的提交异常这种情况只会在等待队列撑满之后才会发生，刚好符合大部分任务没有问题但少部分任务失败的情况，于是确定了问题的原因。
深入分析
虽然找到了调度失败的原因是由于线程池满引起的，但是经过计算，这并不是设计中应该出现的。因为在设计中，业务一共有三台机器分别调度任务，而总任务数量在 300～400 左右。期望中每台机器都应承载 1/3 左右的业务量，也就是约 100～140 个任务左右。在这种情况下，理论上每台机器的线程池都应刚好能满足业务需要的，不应该出现这种情况。而通过查看日志，会发现实际上大部分任务都由一台机器执行，另外两台只分配到了少量任务。这种倾斜直接导致了任务量最大的机器数量爆表，导致线程池处理不及时，进而导致任务提交失败，被 Quartz 标记为异常，停止调度。
误入歧途
既然找到了问题在于 Quartz 调度任务的速度太快，线程池来不及处理，于是想到通过参数配置降低 Quartz 调度线程投递任务的速度，并尝试调升队列缓冲来解决这个问题。通过阅读调度器的代码，找到如下逻辑：
@Override
public void run() {
int acquiresFailed = 0;
while (!halted.get()) {
try {
// do some process states check
int availThreadCount = qsRsrcs.getThreadPool().blockForAvailableThreads();
if(availThreadCount > 0) { // will always be true, due to semantics of blockForAvailableThreads...
List<OperableTrigger> triggers;
long now = System.currentTimeMillis();
clearSignaledSchedulingChange();
try {
triggers = qsRsrcs.getJobStore().acquireNextTriggers(
now + idleWaitTime, Math.min(availThreadCount, qsRsrcs.getMaxBatchSize()), qsRsrcs.getBatchTimeWindow());
acquiresFailed = 0;
if (log.isDebugEnabled())
log.debug("batch acquisition of " + (triggers == null ? 0 : triggers.size()) + " triggers");
} catch (JobPersistenceException jpe) {
// do exception process
continue;
} catch (RuntimeException e) {
// do exception process
continue;
}
if (triggers != null && !triggers.isEmpty()) {
now = System.currentTimeMillis();
long triggerTime = triggers.get(0).getNextFireTime().getTime();
long timeUntilTrigger = triggerTime - now;
while(timeUntilTrigger > 2) {
synchronized (sigLock) {
if (halted.get()) {
break;
}
if (!isCandidateNewTimeEarlierWithinReason(triggerTime, false)) {
try {
// we could have blocked a long while
// on 'synchronize', so we must recompute
now = System.currentTimeMillis();
timeUntilTrigger = triggerTime - now;
if(timeUntilTrigger >= 1)
sigLock.wait(timeUntilTrigger);
} catch (InterruptedException ignore) {
}
}
}
if(releaseIfScheduleChangedSignificantly(triggers, triggerTime)) {
break;
}
now = System.currentTimeMillis();
timeUntilTrigger = triggerTime - now;
}
// do some check
if(goAhead) {
try {
List<TriggerFiredResult> res = qsRsrcs.getJobStore().triggersFired(triggers);
if(res != null)
bndles = res;
} catch (SchedulerException se) {
// do exception process
continue;
}
}
for (int i = 0; i < bndles.size(); i++) {
TriggerFiredResult result = bndles.get(i);
TriggerFiredBundle bndle = result.getTriggerFiredBundle();
Exception exception = result.getException();
// do some check
JobRunShell shell = null;
try {
shell = qsRsrcs.getJobRunShellFactory().createJobRunShell(bndle);
shell.initialize(qs);
} catch (SchedulerException se) {
qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
continue;
}
if (qsRsrcs.getThreadPool().runInThread(shell) == false) {
// this case should never happen, as it is indicative of the
// scheduler being shutdown or a bug in the thread pool or
// a thread pool being used concurrently - which the docs
// say not to do...
getLog().error("ThreadPool.runInThread() return false!");
qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
}
}
continue; // while (!halted)
}
} else { // if(availThreadCount > 0)
// should never happen, if threadPool.blockForAvailableThreads() follows contract
continue; // while (!halted)
}
long now = System.currentTimeMillis();
long waitTime = now + getRandomizedIdleWaitTime();
long timeUntilContinue = waitTime - now;
synchronized(sigLock) {
try {
if(!halted.get()) {
// QTZ-336 A job might have been completed in the mean time and we might have
// missed the scheduled changed signal by not waiting for the notify() yet
// Check that before waiting for too long in case this very job needs to be
// scheduled very soon
if (!isScheduleChanged()) {
sigLock.wait(timeUntilContinue);
}
}
} catch (InterruptedException ignore) {
}
}
} catch(RuntimeException re) {
getLog().error("Runtime error occurred in main trigger firing loop.", re);
}
} // while (!halted)
// drop references to scheduler stuff to aid garbage collection...
qs = null;
qsRsrcs = null;
}这段是 Quartz 调度线程的主要逻辑，注意其中的这段：
triggers = qsRsrcs.getJobStore().acquireNextTriggers(
now + idleWaitTime, Math.min(availThreadCount, qsRsrcs.getMaxBatchSize()), qsRsrcs.getBatchTimeWindow());这里可以看到，Quartz 每次从 DB 拉取的任务数量与线程池的可用线程数和一个参数 MaxBatchSize 有关。根据查阅到的一些文章，说此处 Quartz 会每次拉取线程数个任务。因此怀疑这里是由于工作线程池的线程数量过大，导致任务都被一台机器拉取，导致的负载不均衡。于是尝试调小线程池的参数，来缓解拉取任务过多的问题。这里要说下，这个怀疑是错误的！让我误入歧途。具体原因会在后面说明。
问题“解决“
通过调整此处线程池的参数，任务执行出错的问题再也没有出现。本以为所有的问题就这样解决了，没想到却引来了另一个更棘手的问题：调度延迟。
任务调度延迟
问题现象
接用户反馈，部分每分钟执行一次的定时任务，出现了同一分钟内执行两次的情况。在任务的执行历史里可以明显看到 12:01:09 有一次执行，12:01:22 的时候又出现了一次执行。
找出原因
由于 Quartz 调度器本身是不太容易犯重复调度这样的错误的，因此第一时间考虑是任务调度延迟导致的。通过观察用户的定时任务，发现实际上该任务在 11:59:02 12:01:09 和 12:01:22 分别调度一次。因此可以确定，12:01 的两次调度，一次为正常的调度，一次为 12:00 应当调度的任务但是因为某些原因延迟了。这样才导致整个调度看起来就像是在 12:01 的之后重复调度了一次。
那么现在的问题就在于调度延迟了。由于之前比较激进的调整过线程池的参数，因此这里还是主要考虑在线程池周边找问题。通过调大线程池的参数，可以明显的发现总体调度延迟飞速降低。但是在测试的过程中，还是在日志里发现了一点之前忽略的小问题：
[2021-04-16 20:27:00.051][|][threadPoolTaskExecutor-1] Execute task|1|1
[2021-04-16 20:27:00.100][|][threadPoolTaskExecutor-2] Execute task|1|2
[2021-04-16 20:27:00.157][|][threadPoolTaskExecutor-3] Execute task|1|3
[2021-04-16 20:27:00.213][|][threadPoolTaskExecutor-4] Execute task|1|4
[2021-04-16 20:27:00.268][|][threadPoolTaskExecutor-5] Execute task|1|5
[2021-04-16 20:27:00.323][|][threadPoolTaskExecutor-6] Execute task|1|6
[2021-04-16 20:27:00.379][|][threadPoolTaskExecutor-7] Execute task|1|7
[2021-04-16 20:27:00.437][|][threadPoolTaskExecutor-8] Execute task|1|8
[2021-04-16 20:27:00.492][|][threadPoolTaskExecutor-9] Execute task|1|9
[2021-04-16 20:27:00.554][|][threadPoolTaskExecutor-10] Execute task|1|10
[2021-04-16 20:27:00.610][|][threadPoolTaskExecutor-11] Execute task|1|11
[2021-04-16 20:27:00.667][|][threadPoolTaskExecutor-12] Execute task|1|12
[2021-04-16 20:27:00.721][|][threadPoolTaskExecutor-13] Execute task|1|13
[2021-04-16 20:27:00.775][|][threadPoolTaskExecutor-14] Execute task|1|14
[2021-04-16 20:27:00.831][|][threadPoolTaskExecutor-15] Execute task|1|15
[2021-04-16 20:27:00.885][|][threadPoolTaskExecutor-16] Execute task|1|16
[2021-04-16 20:27:00.937][|][threadPoolTaskExecutor-17] Execute task|1|17
[2021-04-16 20:27:00.991][|][threadPoolTaskExecutor-18] Execute task|1|18
[2021-04-16 20:27:01.044][|][threadPoolTaskExecutor-19] Execute task|1|19
[2021-04-16 20:27:01.098][|][threadPoolTaskExecutor-20] Execute task|1|20
[2021-04-16 20:27:01.152][|][threadPoolTaskExecutor-21] Execute task|1|21
[2021-04-16 20:27:01.206][|][threadPoolTaskExecutor-22] Execute task|1|22
[2021-04-16 20:27:01.261][|][threadPoolTaskExecutor-23] Execute task|1|23
[2021-04-16 20:27:01.315][|][threadPoolTaskExecutor-24] Execute task|1|24
[2021-04-16 20:27:01.372][|][threadPoolTaskExecutor-25] Execute task|1|25
[2021-04-16 20:27:01.427][|][threadPoolTaskExecutor-26] Execute task|1|26
[2021-04-16 20:27:01.481][|][threadPoolTaskExecutor-27] Execute task|1|27
[2021-04-16 20:27:01.536][|][threadPoolTaskExecutor-28] Execute task|1|28
[2021-04-16 20:27:01.590][|][threadPoolTaskExecutor-29] Execute task|1|29
[2021-04-16 20:27:01.644][|][threadPoolTaskExecutor-30] Execute task|1|30
[2021-04-16 20:27:01.698][|][threadPoolTaskExecutor-31] Execute task|1|31
[2021-04-16 20:27:01.757][|][threadPoolTaskExecutor-32] Execute task|1|32
[2021-04-16 20:27:01.811][|][threadPoolTaskExecutor-33] Execute task|1|33
[2021-04-16 20:27:01.866][|][threadPoolTaskExecutor-34] Execute task|1|34
[2021-04-16 20:27:01.920][|][threadPoolTaskExecutor-35] Execute task|1|35
[2021-04-16 20:27:01.973][|][threadPoolTaskExecutor-36] Execute task|1|36
[2021-04-16 20:27:02.031][|][threadPoolTaskExecutor-37] Execute task|1|37
[2021-04-16 20:27:02.086][|][threadPoolTaskExecutor-38] Execute task|1|38
[2021-04-16 20:27:02.139][|][threadPoolTaskExecutor-39] Execute task|1|39
[2021-04-16 20:27:02.194][|][threadPoolTaskExecutor-40] Execute task|1|40
[2021-04-16 20:27:02.247][|][threadPoolTaskExecutor-41] Execute task|1|41
[2021-04-16 20:27:02.301][|][threadPoolTaskExecutor-42] Execute task|1|42
[2021-04-16 20:27:02.354][|][threadPoolTaskExecutor-43] Execute task|1|43
[2021-04-16 20:27:02.407][|][threadPoolTaskExecutor-44] Execute task|1|44
[2021-04-16 20:27:02.460][|][threadPoolTaskExecutor-45] Execute task|1|45
[2021-04-16 20:27:02.513][|][threadPoolTaskExecutor-46] Execute task|1|46
[2021-04-16 20:27:02.567][|][threadPoolTaskExecutor-47] Execute task|1|47
[2021-04-16 20:27:02.620][|][threadPoolTaskExecutor-48] Execute task|1|48
[2021-04-16 20:27:02.680][|][threadPoolTaskExecutor-49] Execute task|1|49
[2021-04-16 20:27:02.734][|][threadPoolTaskExecutor-50] Execute task|1|50可以看到，日志里每两个任务的启动时间，都间隔了 50ms 左右。这个时间并不在预期中。按照设想，Quartz 应该一次性拿可用线程数个任务，然后批量提交才对。如果是批量提交到线程池，正常情况下不应有这么大的启动延迟。就算是因为 CPU 调度的原因，在这台 4C 的机器上，前四个任务的启动时间也不应有特别巨大的偏差才对。而且这台测试机为了避免干扰，除了必要的 SSH 等服务外，没有运行任何其他服务，也不存在 CPU 或内存争抢的情况。
为了确认猜想，使用相同的参数创建了相同的线程池，并使用循环批量提交任务，来测试线程池内线程的启动延迟：
ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
threadPoolTaskExecutor.setCorePoolSize(150);
threadPoolTaskExecutor.setMaxPoolSize(300);
threadPoolTaskExecutor.setQueueCapacity(150);
threadPoolTaskExecutor.initialize();
int count = 0;
while (count < 200) {
threadPoolTaskExecutor.execute(() -> {
log.info("Execute start at {}", System.currentTimeMillis());
try {
Thread.sleep(2_000);
} catch (InterruptedException e) {
log.error("Interrupted exception while execute task!", e);
Thread.interrupted();
}
log.info("Execute end at {}", System.currentTimeMillis());
});
count++;
}经过测试，得到的日志输出是这样的：
[2021-04-17 11:29:06.360][|][ThreadPoolTaskExecutor-1] Execute start
[2021-04-17 11:29:06.361][|][ThreadPoolTaskExecutor-2] Execute start
[2021-04-17 11:29:06.371][|][ThreadPoolTaskExecutor-6] Execute start
[2021-04-17 11:29:06.371][|][ThreadPoolTaskExecutor-5] Execute start
[2021-04-17 11:29:06.372][|][ThreadPoolTaskExecutor-7] Execute start
[2021-04-17 11:29:06.369][|][ThreadPoolTaskExecutor-4] Execute start
[2021-04-17 11:29:06.362][|][ThreadPoolTaskExecutor-3] Execute start
[2021-04-17 11:29:06.374][|][ThreadPoolTaskExecutor-8] Execute start
[2021-04-17 11:29:06.375][|][ThreadPoolTaskExecutor-9] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-11] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-10] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-12] Execute start
[2021-04-17 11:29:06.384][|][ThreadPoolTaskExecutor-13] Execute start
[2021-04-17 11:29:06.384][|][ThreadPoolTaskExecutor-14] Execute start
[2021-04-17 11:29:06.385][|][ThreadPoolTaskExecutor-15] Execute start
[2021-04-17 11:29:06.385][|][ThreadPoolTaskExecutor-16] Execute start
[2021-04-17 11:29:06.386][|][ThreadPoolTaskExecutor-18] Execute start
[2021-04-17 11:29:06.386][|][ThreadPoolTaskExecutor-17] Execute start
[2021-04-17 11:29:06.392][|][ThreadPoolTaskExecutor-19] Execute start
[2021-04-17 11:29:06.393][|][ThreadPoolTaskExecutor-20] Execute start
[2021-04-17 11:29:06.393][|][ThreadPoolTaskExecutor-21] Execute start
[2021-04-17 11:29:06.394][|][ThreadPoolTaskExecutor-22] Execute start
[2021-04-17 11:29:06.394][|][ThreadPoolTaskExecutor-23] Execute start
[2021-04-17 11:29:06.395][|][ThreadPoolTaskExecutor-24] Execute start
[2021-04-17 11:29:06.395][|][ThreadPoolTaskExecutor-25] Execute start
[2021-04-17 11:29:06.396][|][ThreadPoolTaskExecutor-26] Execute start
[2021-04-17 11:29:06.396][|][ThreadPoolTaskExecutor-27] Execute start
[2021-04-17 11:29:06.397][|][ThreadPoolTaskExecutor-28] Execute start
[2021-04-17 11:29:06.397][|][ThreadPoolTaskExecutor-29] Execute start
[2021-04-17 11:29:06.398][|][ThreadPoolTaskExecutor-30] Execute start
[2021-04-17 11:29:06.398][|][ThreadPoolTaskExecutor-31] Execute start
[2021-04-17 11:29:06.399][|][ThreadPoolTaskExecutor-32] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-33] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-34] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-35] Execute start
[2021-04-17 11:29:06.401][|][ThreadPoolTaskExecutor-36] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-37] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-38] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-39] Execute start
[2021-04-17 11:29:06.403][|][ThreadPoolTaskExecutor-40] Execute start
[2021-04-17 11:29:06.410][|][ThreadPoolTaskExecutor-42] Execute start
[2021-04-17 11:29:06.411][|][ThreadPoolTaskExecutor-41] Execute start
[2021-04-17 11:29:06.411][|][ThreadPoolTaskExecutor-43] Execute start
[2021-04-17 11:29:06.412][|][ThreadPoolTaskExecutor-44] Execute start
[2021-04-17 11:29:06.412][|][ThreadPoolTaskExecutor-45] Execute start
[2021-04-17 11:29:06.413][|][ThreadPoolTaskExecutor-46] Execute start
[2021-04-17 11:29:06.421][|][ThreadPoolTaskExecutor-47] Execute start
[2021-04-17 11:29:06.422][|][ThreadPoolTaskExecutor-48] Execute start
[2021-04-17 11:29:06.424][|][ThreadPoolTaskExecutor-49] Execute start
[2021-04-17 11:29:06.424][|][ThreadPoolTaskExecutor-50] Execute start可以看到，在相同的一台四核的机器上，除了最开始启动较慢外，余下的任务启动时间的偏差基本在 1ms 内。50 个任务全部启动也只用了 60ms 左右。前 150 个任务的启动时间总过也就相差 200ms 左右。这个结果表明，定时任务调度时一定还有其他耗时操作穿插其间，导致任务的提交本身存在延迟，才导致了前 50 个任务的启动时间偏差接近 3s。
深入分析
于是回到代码本身，深入分析 Quartz 的任务调度和提交逻辑。参考前面提供的 QuartzSchedulerThread 主调度线程的代码，我们可以把整个调度过程进行一个阶段划分：
- 等待工作线程池出现可用线程
- 根据可用线程数和最大批量大小从 DB 中取出将要触发的 Trigger
- 循环等待，直到离最近一个要出发的 Trigger 的触发时间还有 2ms
- 更新 DB 设置当前批次 Trigger 的触发状态
- 提交 Trigger 到执行线程池
其中 2 4 两步需要访问 DB 更新 Trigger 的状态，并且需要获取 TRIGGER_ACCESS 锁。按照访问 DB 的一般耗时估算，一次 DB 操作大约会消耗 5～10ms 的时间，那么这两步的 DB 操作大约每次会消耗 15～20ms 左右的时间，刚好与我们之前观察到的 50ms 的延迟接近。
可是按照正常逻辑，此处 Quartz 应该是批量去取 Trigger，应该每一批 Trigger 消耗 50ms 才是正常现象。现在每一个 Trigger 都间隔了 50ms，说明此处的批量处理一定出现了问题。于是单独深入批量拉取 Trigger 这段代码，发现之前被忽略的 maxBatchSize 有问题。由于理所当然的认为该选项的值一定会比较大，不太可能成为瓶颈，之前就没有仔细追踪这个参数。现在经过追溯，发现该值在 org.quartz.core.QuartzSchedulerResources 中存在一个默认值 1。也就是说如果没有特殊配置的话，这里的批量永远是单个拉取。这也说明了，之前的猜测是完全错误的。负载不均匀导致队列爆掉并不是因为 Quartz 批量过大导致的，而是另有原因。
尝试修复
既然找到了这个变量漏设置了值，那就修改这里的默认值，再进行测试。这里这个变量值需要修改 Quartz 的配置文件，增加 org.quartz.scheduler.batchTriggerAcquisitionMaxCount 配置项。这里修改成 50 进行测试，配合线程池的 core size 150，应该可以达到每批次处理 50 个 Trigger 的目的。修改后的日志如下：
[2021-04-17 13:45:00.051][|][threadPoolTaskExecutor-1] Execute task|1|1
[2021-04-17 13:45:00.108][|][threadPoolTaskExecutor-2] Execute task|1|2
[2021-04-17 13:45:00.173][|][threadPoolTaskExecutor-3] Execute task|1|3
[2021-04-17 13:45:00.231][|][threadPoolTaskExecutor-4] Execute task|1|4
[2021-04-17 13:45:00.288][|][threadPoolTaskExecutor-5] Execute task|1|5
[2021-04-17 13:45:00.346][|][threadPoolTaskExecutor-6] Execute task|1|6
[2021-04-17 13:45:00.403][|][threadPoolTaskExecutor-7] Execute task|1|7
[2021-04-17 13:45:00.462][|][threadPoolTaskExecutor-8] Execute task|1|8
[2021-04-17 13:45:00.518][|][threadPoolTaskExecutor-9] Execute task|1|9
[2021-04-17 13:45:00.574][|][threadPoolTaskExecutor-10] Execute task|1|10
[2021-04-17 13:45:00.629][|][threadPoolTaskExecutor-11] Execute task|1|11
[2021-04-17 13:45:00.687][|][threadPoolTaskExecutor-12] Execute task|1|12
[2021-04-17 13:45:00.741][|][threadPoolTaskExecutor-13] Execute task|1|13
[2021-04-17 13:45:00.795][|][threadPoolTaskExecutor-14] Execute task|1|14
[2021-04-17 13:45:00.849][|][threadPoolTaskExecutor-15] Execute task|1|15
[2021-04-17 13:45:00.915][|][threadPoolTaskExecutor-16] Execute task|1|16
[2021-04-17 13:45:00.971][|][threadPoolTaskExecutor-17] Execute task|1|17
[2021-04-17 13:45:01.026][|][threadPoolTaskExecutor-18] Execute task|1|18
[2021-04-17 13:45:01.081][|][threadPoolTaskExecutor-19] Execute task|1|19
[2021-04-17 13:45:01.135][|][threadPoolTaskExecutor-20] Execute task|1|20奇怪的事情发生了，这个参数的修改完全没有起作用，Quartz 还是一个个任务调度的，而不是批量调度。同时在为了测试专门开启的调度引擎的 Debug 日志中也发现了相关日志：
[2021-04-17 13:45:00.076][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.135][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.201][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.258][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.315][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.373][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.431][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.488][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.545][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.600][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers从这里可以看出，调度器确实每次只取了一个 Trigger 进行触发。这就很奇怪了，明明我们已经修改了最大批量值的参数，却看起来像没有生效。考虑到这里的批量值是由两个参数决定的，那么问题一定出在二者之间
- 线程池可用线程数有问题，获取到的数据不是设置的 150 个线程
- maxBatchSize 参数设置没有生效，仍然为 1
由于这两个参数在调度器之外比较用非入侵的方式检测，于是决定直接上 IDEA 用远程调试来解决：
在调度线程批量拉取 Trigger 的地方设置断点，通过查看两个变量的值，发现了问题。这里可以清晰的看到 maxBatchSize 已经变为我们设置的 50 了。但是 availThreadCount 却不是预想中的 150，而是 1。于是检查一下这个线程池：
可以看到，此处用来接收任务的线程池居然是 LocalTaskExecutorThreadPool 类型的线程池，而不是我们在配置里提供给 Quartz 的。而在初始化时提供给 Quartz 的线程池变成了该线程池内部的一个 executor。那这个线程池是哪来的呢？跟进去看下：
可以看到这个线程池是 spring 对于我们实际使用的线程池的一个封装。这个线程池内部的 taskExecutor 才是真正的由我们配置的执行任务的线程池。而这个封装中，由于内部的 executor 是不确定的，所以为了简单，此处的可用线程数查询居然永久返回 1。至此问题的根源找到了：因为 LocalTaskExecutorThreadPool 封装了我们提供给 Quartz 的线程池，且该封装在获取可用线程数时永远返回 1，导致了我们修改 maxBatchSize 没有生效。
再次深入
那么这里其实还有个问题，就是这个 LocalTaskExecutorThreadPool 是从何而来，为何没有直接使用我们构造好的 ThreadPoolTaskExecutor 呢？
经过追踪，发现这个线程池的来源在这里：
可以看到，这是 Spring 对于 Quartz 初始化的一个封装。在这个封装中，如果 Spring 发现我们尝试使用自己配置的一个任务执行器的话，就会默认用 LocalTaskExecutorThreadPool 来做一个包装，除非在配置文件中配置 org.quartz.threadPool.class 显示的覆盖这个参数。而通过阅读配置，我发现这里确实是没有设置值。通过参考 Quartz 本身的初始化过程，猜测当时没有设置这个值的原因是因为 Quartz 本身默认会使用 SimpleThreadPool 来运行任务，因此考虑这个设置是多余的，于是没有进行设置。但是在考虑的过程中却忽略了 Spring 这块，导致实际的效果与预期不一致。
真相大白
至此，这里无法进行批量调度导致调度延迟的各个原因终于复出水面。在这个问题中，由于多个配置之间的互相作用最终导致了这个结果。主要有以下几点：
- maxBatchSize 的默认值为 1
LocalTaskExecutorThreadPool对于可用线程数永远返回 1- Quartz 的默认线程池是
SimpleThreadPool，但 Spring 在使用了自定义工作线程池的情况下默认为LocalTaskExecutorThreadPool org.quartz.threadPool.class的默认行为与 Quartz 匹配，但与 Spring 不匹配
这里针对 3 多说几句。后面经过阅读代码，发现 Quartz 调度线程需要的 ThreadPool 并不是通常使用的 java.util.concurrent.ThreadPoolExecutor 而是 Quartz 自行封装的 org.quartz.spi.ThreadPool。因此，当我们要求 Spring 使用我们自定义的 ThreadPoolExecutor 来执行工作任务时，Spring 别无选择，必须对我们提供的 ThreadPoolExecutor 做一次封装，才能提供给 Quartz 调度线程使用。而一开始在编写代码时对这里没有深入研究则埋下了一个大坑。
因此这里的解决方案也很简单，直接去掉自定义线程池，使用 Quartz 提供的 SimpleThreadPool 来处理工作负载即可。而且这里修改为 Quartz 自身的 SimpleThreadPool 来处理工作负载后，原先的调度异常的问题也自然而然的解决了。具体原因见总结。修改配置后再进行测试，看到这样的日志输出：
[2021-04-17 15:50:09.821][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 0 triggers
[2021-04-17 15:50:33.989][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:01.551][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:02.948][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:04.009][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 6 triggers
[2021-04-17 15:51:04.723][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 44 triggers
[2021-04-17 15:51:06.241][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:07.614][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 26 triggers
[2021-04-17 15:51:08.500][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 31 triggers
[2021-04-17 15:51:09.448][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 43 triggers
[2021-04-17 15:51:10.600][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 31 triggers
[2021-04-17 15:51:11.564][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 19 triggers
[2021-04-17 15:51:11.884][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 0 triggers
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-5] Execute task|1|5
[2021-04-17 15:51:00.806][|][quartz-scheduler_Worker-3] Execute task|1|3
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-20] Execute task|1|20
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-21] Execute task|1|21
[2021-04-17 15:51:00.813][|][quartz-scheduler_Worker-22] Execute task|1|22
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-6] Execute task|1|6
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-9] Execute task|1|9
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-12] Execute task|1|12
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-17] Execute task|1|17
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-13] Execute task|1|13
[2021-04-17 15:51:00.818][|][quartz-scheduler_Worker-26] Execute task|1|26
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-23] Execute task|1|23
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-4] Execute task|1|4
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-10] Execute task|1|10
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-18] Execute task|1|18
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-8] Execute task|1|8
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-19] Execute task|1|19
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-14] Execute task|1|14
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-7] Execute task|1|7
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-16] Execute task|1|16
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-11] Execute task|1|11
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-15] Execute task|1|15
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-1] Execute task|1|1
[2021-04-17 15:51:00.816][|][quartz-scheduler_Worker-24] Execute task|1|24
[2021-04-17 15:51:00.806][|][quartz-scheduler_Worker-2] Execute task|1|2
[2021-04-17 15:51:00.816][|][quartz-scheduler_Worker-25] Execute task|1|25
[2021-04-17 15:51:00.827][|][quartz-scheduler_Worker-27] Execute task|1|27
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-31] Execute task|1|31
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-29] Execute task|1|29
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-32] Execute task|1|32
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-30] Execute task|1|30
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-28] Execute task|1|28
[2021-04-17 15:51:00.830][|][quartz-scheduler_Worker-33] Execute task|1|33
[2021-04-17 15:51:00.831][|][quartz-scheduler_Worker-35] Execute task|1|35
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-34] Execute task|1|34
[2021-04-17 15:51:00.832][|][quartz-scheduler_Worker-36] Execute task|1|36
[2021-04-17 15:51:00.834][|][quartz-scheduler_Worker-37] Execute task|1|37
[2021-04-17 15:51:00.834][|][quartz-scheduler_Worker-38] Execute task|1|38
[2021-04-17 15:51:00.836][|][quartz-scheduler_Worker-41] Execute task|1|41
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-39] Execute task|1|39
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-40] Execute task|1|40
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-42] Execute task|1|42
[2021-04-17 15:51:00.838][|][quartz-scheduler_Worker-43] Execute task|1|43
[2021-04-17 15:51:00.838][|][quartz-scheduler_Worker-44] Execute task|1|44
[2021-04-17 15:51:00.839][|][quartz-scheduler_Worker-45] Execute task|1|45
[2021-04-17 15:51:00.843][|][quartz-scheduler_Worker-48] Execute task|1|48
[2021-04-17 15:51:00.843][|][quartz-scheduler_Worker-46] Execute task|1|46
[2021-04-17 15:51:00.853][|][quartz-scheduler_Worker-49] Execute task|1|49
[2021-04-17 15:51:00.857][|][quartz-scheduler_Worker-47] Execute task|1|47
[2021-04-17 15:51:00.862][|][quartz-scheduler_Worker-50] Execute task|1|50第一段调度器的日志显示现在已经成功的使用批量的方式来进行 Trigger 的拉取了，每次拉取 50 个。在拉取了 150 个任务之后，由于线程都已在执行任务，所以只有 6 个空闲线程释放，因此拉取了 6 个任务。
第二段是实际的任务执行日志。可以看到在这段执行过程中，大约有 25 个任务在 20ms 内启动完成，50 个任务全部启动也只消耗了约 50ms 的时间，已经比原先大大提升。
同时，对于负载不均匀的问题，在修改前，三台机器的负载为：1:2:497。修改之后再次测试，变为：100:151:249。负载不均匀的问题已经基本解决。
总结
注意事项
通过这次问题排查，认识到了一些在 Quartz 搭配 Spring 使用时需要注意的问题：
- 尽量不要使用自定义线程池，而是使用 Quartz 实现的 SimpleThreadPool
- 搭配使用时，不光要留意 Quartz 本身对于配置项的默认值处理，也要注意 Spring 对于配置项的处理
- Quartz 的调度误差是由多方面原因造成的，需要综合考虑配置项之间的相互作用逻辑
- 分析问题时需要严格测试，而不能想当然的进行调整
调度异常&负载不均原因
另外再来看一下最开始遇到的调度异常&负载不均的问题。综合后续的所有分析可知，在默认情况下，Quartz 的调度逻辑是这样的：
可以看到在这个默认配置下，由于存在一个阻塞等待可用线程（org.quartz.simpl.SimpleThreadPool#blockForAvailableThreads）的操作，可以保证当本机的线程全部繁忙的时候，本机的调度线程不会去获取锁，自然而然的让别的实例来接手余下的任务调度工作。同时，由于这里的阻塞等待，保证了当本机线程全忙的时候不会有任何新任务进入，也就保证了不会出现提交失败的问题。
而当使用自定义线程池的时候，调度流程变成了这样：
在这个工作模式下，阻塞等待没有了。就算自定义线程池中的线程全忙、队列已满，此处还是会返回有一个可用线程。所以此时，调度线程的工作模式就变成了，不管线程池是否爆满，始终抢夺任务并继续提交。正是因为这里没有判定线程池是否满的逻辑，导致了最初的提交失败。而且由于不再等待可用线程，这里的循环变成了 加锁->拉 Trigger->提交 的循环，从而导致最初最先启动的线程在抢锁的过程中有极大的优势（没抢到锁会强制等待，而等待的时候锁已经又被最先启动的线程抢了），从而导致负载的严重失衡。
所以为了解决提交失败和负载不均的问题，最简单的方法是不要使用自定义线程池，而是通过 org.quartz.threadPool.class 设置使用 SimpleThreadPool，并根据机器负载调节线程数量。如果一定要使用自定义线程池的话，则必须实现 Quartz 提供的 org.quartz.spi.ThreadPool 接口，并实现阻塞等待可用线程的逻辑。千万不能直接使用 Spring 提供的 LocalTaskExecutorThreadPool。
调度延迟产生的原因
根据本次分析的过程可以看出，Quartz 的调度延迟主要由以下几个方面组成：
- 同步加锁延迟。当 Quartz 使用DB作为集群持久化存储的场景下，为了保证调度秩序，避免重复调度或漏调度，每一次 DB 操作都要进行加锁。而每次调度时，需要先从 DB 读取要触发的
Trigger信息并更新状态为ACQUIRED，然后在将要触发时更新状态到EXECUTING，之后才会向工作线程池提交任务。虽然在读取 Trigger 信息的时候大部分操作都不是批量进行的，但是加锁操作是针对一批任务的。考虑到正常的 DB 读写耗时在 5～10ms 左右，如果不进行批量操作的话，按照 50 个任务一批计算，每一批的加锁时间就白白增加了 250～500ms。因此，进行批量拉取可以有效的减小 DB 加锁操作带来的调度延迟。同时，考虑到锁的竞争会导致线程等待，批量加锁操作还可以有效的降低锁争抢，提升整体效率。如果业务场景对调度延迟比较敏感，应考虑使用性能更好的独立 DB 实例，并尽量降低 Quartz 实例到 DB 之间的网络延迟； - 批量执行排队延迟。如果同时触发的任务数量超过了总集群的线程池上限，则一定会被分为多个批次进行触发，这时就会出现排队延迟。这里每个批次间的排队延迟将取决于任务的执行速度。单个任务执行的越慢则越靠后被触发的批次延迟越大。当总线程数耗尽时，下一次调度一定会等到有线程释放才会开始。理想情况下所有任务都应在一个批次内做完。因此应根据工作负载的情况，对 Quartz 集群进行扩容，增加总线程数，来避免任务进入排队。但是由于成本限制，这个方式往往很难实施。而且在实际使用的过程中，偶尔会出现任务本身的执行耗时不可控的情况。因此在实际使用的过程中，需要根据实际的业务情况，合理调节批量参数和工作线程数。当然在调节工作线程数量时还需要需要考虑到机器实际的负载能力，不能无谓的提高，反而导致负载不均衡的情况出现。同时应当考虑采取异步机制，并通过消息队列等异步化手段，将任务快速分发下去。再结合快速扩容机制，在峰值来临前对执行器进行扩容，来进一步降低延迟。这里推荐异步化任务执行器而不是大量扩容 Quartz 集群的主要原因在于，Quartz 集群本身是一个有状态的集群，相对来说逻辑复杂、任务较重，且存在集群锁，不适合进行快速扩缩容。而在需要大批量调度的场景下，我们的工作负载往往都是无状态、逻辑简单、轻量化的小任务。这种任务最适合配合 K8S 等集群进行快速扩容支撑峰值，并在谷时缩容降低成本；
- CPU调度延迟。当调度线程将任务提交给工作线程池后，工作线程池中的线程最终还需要依赖 CPU 时间片来执行，若调度机器的 CPU 负载较高，或线程池数量不合理，那么线程在真正被 CPU 执行前将会有较大等待。为了尽量减少这里的执行延迟，应将工作线程池部署在 CPU 核数较多且负载不高的机器上。同时应该合理设置工作线程数量，避免一次性触发过多任务。
使用 Quartz 调度器遇到的一些问题 by 桔子小窝 is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.
腻害，碰到了差不多问题，setTaskExecutor可太坑了
非常感谢博主的分享，想问一下，你的job上是否也加了注解：@DisallowConcurrentExecution使基于同一个jobKey的实例（任务）不能同时并发执行。另外我遇到的问题，和您的略微不同，我这边是webservice中定义了大概20多个定时任务，但是某些任务总是运行一段时间（大概几个月后）trigger状态就变为BLOCKED，然后任务也不再执行了，您遇到这种情况么，希望回复，谢谢。