记一次生产调度(Quartz任务未执行)故障的排查
背景
作为平台团队，基于业务需求我们团队开发了一套微服务任务调度平台，投入生产一年多，同时也在不久前宣布对外开源。
有兴趣的同仁可以关注下：SIA-TASK
一 事故现场
- 最近三个月期间收到两次业务同事的反馈：反馈信息任务莫名其妙的不执行了。
1.1 初步排查
其实我在第一次收到这个事故信息是并没有把它非常的重视，从生产运行来看毕竟一年多出了一次事故，只有一个任务出现不执行，自然而然的就让其他特殊原因 给背了锅。
针对第一次事故报告我们仅仅做了简单的排查：
- 查看后台日志有无异常，未发现异常信息
- 其实查看任务状态也是一直处于准备中，任务的调度执行日志并没有输出。
- 怀疑可能是网络问题丢失事件。
- 排查其他项目组的任务执行正常。
- 记录待排查...
1.2 排查结果
- 根据上述内容，所以并没有给出一个能说服的理由，让
网络~其它原因背锅（待观察，当然如果不复出可能就一直是待观察了...），为了不让业务继续阻断，所以在平台portal对该任务进行重新发布，之后再次观察任务执行正常。 - 在我们项目组Jira 记录下此问题。
至此 此次排查任务就草草了事。感觉有点不负责任哈
1.3 事故再次爆发
在上次事故出现之后，过了近三个多月，业务项目组同事又一次提报出现故障，而且和上一次故障的情形非常类似，也是莫名其妙的就不执行了。此时我也猜到肯定和上次事故时原因应该是一样的，该来的还是会来的，该还的还是会还的，一万个草泥马也是瞬间奔腾。
所以... 开始排查之旅。
二 排查
通过百度一通查... 无力... 无力翻墙。只能具体问题具体分析。
还是遵循常规问题的排查步骤，这还是经久不衰的。
2.1 查看现场
2.1.1 确认事故现场
- 平台管理端提示任务已激活，状态为准备中...，查看任务调度日志，没有任务的执行日志，连调度日志都没有。
- 接着查看后台系统日志：
2019-09-20 18:30:03.517 INFO 24661 --- [Zookeeper-TreeCacheListener-3] com.sia.scheduler.zk.monitor.JobMonitor : >>>>>>>>>>尝试抢占JOB，JobGroupName is zma JobKey is zma_20180911105301
2019-09-20 18:30:03.519 INFO 24661 --- [Zookeeper-TreeCacheListener-3] com.sia.core.curator.CuratorClient : getChildren，读取数据成功, path:/SkyWorldOnlineTask/Job/zma/zma_20180911105301
2019-09-20 18:30:03.521 INFO 24661 --- [Zookeeper-TreeCacheListener-3] com.sia.core.curator.CuratorClient : createFixedEphemeralZKNode，创建节点成功，节点地址:/SkyWorldOnlineTask/Job/zma/zma_20180911105301/1xx.1xx.1x0.xx:1xxxx
2019-09-20 18:30:03.524 INFO 24661 --- [Zookeeper-TreeCacheListener-3] com.sia.scheduler.zk.monitor.JobMonitor : >>>>>>>>>> 调度器 ：10x.1xx.1xx.31:19xx9 尝试抢占JOB IS SUCCESS , 开始启动JOB; JobGroupName is zma JobKey is zma_20180911105301
2019-09-20 18:30:03.524 INFO 24661 --- [Zookeeper-TreeCacheListener-3] c.sia.scheduler.service.BasicJobService : >>>>>>>>>> cleanJobCache : clean data from Cache, jobKey=zma_20180911105301
2019-09-20 18:30:03.524 INFO 24661 --- [Zookeeper-TreeCacheListener-3] c.sia.scheduler.service.BasicJobService : >>>>>>>>>> load BasicJob data from database, jobKey=zma_20180911105301
2019-09-20 18:30:03.526 INFO 24661 --- [Zookeeper-TreeCacheListener-3] org.quartz.core.QuartzScheduler : Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started.
- 日志输出任务抢占成功和管理端显示一致，任务的确抢占成功；
-
Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started. 说明Job注册Quartz正常，未出现异常；
根据百度提取信息：可能是并发任务大于调度线程数（虽然内心里已经排除这种可能性-因为我做了这方面的优化，理论上不可能出现）。我对任务增加了触发监听器(TriggerListener)和执行监听器(JobListeners) ,如果出现任务错过没有执行，则会触发时间机制：
部分代码：TriggerListener
@Override
public void triggerFired(Trigger trigger, JobExecutionContext context) {
LOGGER.info("触发JobTrigger事件：[TriggerFired] [{}], [{}]" , context.getFireTime(),context.getJobDetail().getKey().getName());
}
@Override
public void triggerMisfired(Trigger trigger) {
LOGGER.info("触发JobTrigger事件：[triggerMisfired] [{}], [{}]", trigger.getStartTime(), trigger.getJobKey().getName());
}
@Override
public void triggerComplete(Trigger trigger, JobExecutionContext context, Trigger.CompletedExecutionInstruction triggerInstructionCode) {
LOGGER.info("触发JobTrigger事件：[triggerComplete] [{}], [{}]", trigger.getStartTime(), trigger.getJobKey().getName());
}
部分代码：JobListeners
@Override
public void jobToBeExecuted(JobExecutionContext context) {
LOGGER.info("触发Job事件：[jobToBeExecuted] [{}], [{}]" , context.getFireTime(),context.getJobDetail().getKey().getName());
}
@Override
public void jobExecutionVetoed(JobExecutionContext context) {
LOGGER.info("触发Job事件：[jobExecutionVetoed], [{}], [{}]", context.getFireTime(),context.getJobDetail().getKey().getName());
}
结果查询结果 果然不尽人意：
- 没有triggerMisfired ：事件没有被触发。此时也很奇怪，不知为什么？
- 也没有triggerFired：????? 连触发器都没有触发...
- 这个就觉得怪异了，注册quartz通过日志来看的话的确是成功的，但是没有进行触发，这就奇怪了？
- 难道Job真正注册quartz的时候并没有成功，或者再不为人知的时候Job给移除了？
2.2 Quartz注册过程排查
带着对上述的疑问，进行排查，这时候就不得不去翻看下Quartz的源码了,只这里截取部分关键核心代码（去掉一些无关的判断逻辑）。
2.2.1 Quartz 注册Job源码查看
public Date scheduleJob(JobDetail jobDetail,
Trigger trigger) throws SchedulerException {
validateState();
...//省略判断逻辑
Date ft = trig.computeFirstFireTime(cal);
if (ft == null) {
throw new SchedulerException("...");//省略
}
//核心点就在这里：继续看下该方法
resources.getJobStore().storeJobAndTrigger(jobDetail, trig);
notifySchedulerListenersJobAdded(jobDetail);
notifySchedulerThread(trigger.getNextFireTime().getTime());
notifySchedulerListenersSchduled(trigger);
return ft;
}
2.2.2 Quartz 注册Job源码--storeJobAndTrigger
顺便提下，我们平台没有使用Quartz原生的集群方案，自己实现的，持久化方案也是自己实现的，基于Quartz内存机制来衍生的。所以这里我截取的类是RAMJobStore implements JobStore
public void storeJobAndTrigger(JobDetail newJob, OperableTrigger newTrigger) throws JobPersistenceException {
storeJob(newJob, false);
storeTrigger(newTrigger, false);
}
这两个方法的内部实现这里就不展示了，并不是源码分析，简单说下：其实内部维护了诸多个HashMap来存储Job：
- HashMap<JobKey, JobWrapper> jobsByKey
- HashMap<String, HashMap<JobKey, JobWrapper>> jobsByGroup
- HashMap<TriggerKey, TriggerWrapper> triggersByKey
- ...
通过源码可知，正是这个RAMJobStore内部的Map容器存储我们注册给Quartz的Job对象，所以有必要真正去查看下其内部是否真的存在我们注册的Job。
OK~ 撸起袖子开干！！！
2.3 Dump
上堡垒机（对比两次提报的故障，发现都是同一台服务），去拉取下当前进程的Dump，（顺便关注了下机器信息：CPU，内存均正常，所以也就无需关注JVM一些问题了）。
[root@localhost ~]# jmap -dump:format=b,file=/xxxxa/xxxxb/xxxxc/heap.hprof 22986
2.3.1 jhat: 分析 heapdump 文件
jhat 用于分析 heapdump 文件，它会建立一个 HTTP/HTML 服务器，让用户可以在浏览器上查看分析结果。这里我只关注对象存在与否，所以JDK命令行工具jhat 即可。
bogon:D-disk maozhengwei$ jhat heap.hprof
Reading from heap.hprof...
Dump file created Wed Jun 12 11:13:15 CST 2019
Snapshot read, resolving...
Resolving 97551 objects...
Chasing references, expect 19 dots...................
Eliminating duplicate references...................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.
知道数据内存在什么数据结构[RAMJobStore]，所以直接快速查找：
查找Quartz的RAMJobStore 找到之后选择进入，如图1-RAMJobStore所示：
图1-RAMJobStore
2.3.2 RAMJobStore-Instances
Include subclasses
这里我们选择Include subclasses 选择进入，如图2-Include subclasses所示：
图2-Include subclasses
这时候我们就能看到RAMJobStore 内部结构。当然我们不用了解源码看到这个字面名称也能猜测到这些内部结构是用来做什么的。
这里暂不逐一解释：之后进行说明：
我们直接关注jobsByKey 与 triggersByKey 通过上面2.2.2 Quartz 注册Job源码--storeJobAndTrigger针对Job注册源码的分析了解这个是用来存储我们注册的Job。
这里我们先选择jobsByKey 如图3-RAMJobStore-Instance所示：
图3-RAMJobStore-Instance
通过size 判断该实例内部注册了65个Job，这个与我们通过zk存储的数据是一致的，这没问题。（内心不由的感觉Job应该是注册成功了，虽然知道了，但还是抱着侥幸心理去查看：不到黄河心不死）。
如图4-RAMJobStore-jobsByKey所示：
图4-RAMJobStore-jobsByKey
这时只需查看下HashMap的table中是否存在出现异常（不运行的Job）。如图4-RAMJobStore-jobsByKey所示选择table进入其内部
2.3.2 RAMJobStore-HashMap#table
还算比较幸运该实例上面注册的任务并不是很多，逐个找不算太麻烦，如果遇到上千的实例节点，想想也是件郁闷的事情。继续排查挨个查询，最终和内心的猜测是一样的如果注册是成功的，这块并没有异常。
下图是确定的目标Job对象:图5-目标Job对象
图5-目标Job对象
查询对象内部数据也是没有问题，这块说明注册Job是没有问题，想到还有一种可能，Job不光只注册Job，同时还会注册JobTrigger(这块在2.2.2小结源码说明)，接着思路继续跟进，返回再去查看Trigger注册是否成功。
根据图图3-RAMJobStore-Instance上面的提示框选择TriggersByJob进入，方式和查询Job一样，不在重复赘述。
下图图6-TriggersByJob就是Trigger：
图6-TriggersByJob
Trigger注册也是没有问题，顺便我们看了下下次触发事件，也的确说明这个时间对比当前时间已经过去了很久，所以可以很肯定的是该Job压根就没有触发。然后看了下时间，这个时间正好是卡在我们生产zk服务集群由于服务器更换迁移导致网络中断的时间非常吻合。（因为SIA-TASK在设计架构的时候充分考虑了这种突发情况，所以针对这次问题足以稳定面对，大部分任务都是没有问题，只有这个问题出现此种情形）。
虽然知道问题的起点以及事故原始现场，但是并没有找出任务不触发的根本原因。
2.4 再次回到Quartz 源码中
到此为止 针对Dump的分析暂时告一段落。又不得不再次回到Quartz中去查询Job&Trigger都注册成功的情况下任务依旧不执行的原因（已经排除调度线程不足的情况）。
再次分析RAMJobStore.class（笔者读过Quartz的源码，所以这里就直接给出查找方法和原因，就不在逐个说明看源码的过程）
2.4.1 RAMJobStore#triggersFired
这里重点关注这个方法triggersFired，为什么关注这个方法，这个方法是quartz scheduler进行对获取的Job进行触发调用该方法
下面是这个方法的部分内容：
/**
* <p>
* Inform the <code>JobStore</code> that the scheduler is now firing the
* given <code>Trigger</code> (executing its associated <code>Job</code>),
* that it had previously acquired (reserved).
* </p>
*/
public List<TriggerFiredResult> triggersFired(List<OperableTrigger> firedTriggers) {
synchronized (lock) {
List<TriggerFiredResult> results = new ArrayList<TriggerFiredResult>();
for (OperableTrigger trigger : firedTriggers) {
TriggerWrapper tw = triggersByKey.get(trigger.getKey());
// was the trigger deleted since being acquired?
if (tw == null || tw.trigger == null) {
continue;
}
...
JobDetail job = bndle.getJobDetail();
//重点关注这里：当初在设计SIA-Task 针对任务的流程设计，规定任务不允许是并发执行。
//所以特别关注了下这块代码:
//根据代码内容可以明了 Job的并发限制是通过两个Map之间来回进行转换,来达到限制并发的效果
if (job.isConcurrentExectionDisallowed()) {
ArrayList<TriggerWrapper> trigs = getTriggerWrappersForJob(job.getKey());
for (TriggerWrapper ttw : trigs) {
if (ttw.state == TriggerWrapper.STATE_WAITING) {
ttw.state = TriggerWrapper.STATE_BLOCKED;
}
if (ttw.state == TriggerWrapper.STATE_PAUSED) {
ttw.state = TriggerWrapper.STATE_PAUSED_BLOCKED;
}
timeTriggers.remove(ttw);
}
blockedJobs.add(job.getKey());
} else if (tw.trigger.getNextFireTime() != null) {
synchronized (lock) {
timeTriggers.add(tw);
}
}
results.add(new TriggerFiredResult(bndle));
}
return results;
}
}
重点关注这里：
当初在设计SIA-Task 针对任务的流程设计，规定任务不允许是并发执行。所以特别关注了下这块代码:根据代码内容可以明了 Job的并发限制是通过两个容器（blockedJobs,timeTriggers）之间来回进行转换,来达到限制并发的效果。
这里我就大胆的猜测以及提出一些疑问：
- 疑问1 是不是我们的Job添加之后处于某种原因，它一直处于blockedJobs这个容器中并没有得到释放 。
- 疑问2 是不是任务处于blockedJobs容器中，就不会处于timeTriggers中了
-
疑问3 什么时候任务移除blockedJobs。
对比下面的源码，不难得出第二条猜测是合理的。那么我们就需要验证下第一条以及寻找最后一条的答案。
最好的也最直接的方法就是看当前的内存快照，直接了当的说明问题。
2.4 轮回到Dump中
又一次切换到dump试图中， 其实排查问题也就是这个样子。（当年刘备请诸葛亮还三顾茅庐。更何况为了追求真理也是拼了，扯淡结束）
2.4.1 RAMJobStore-blockedJobs
- 这次只需关注RAMJobStore-Instance 内部的两个结构即可：容器（blockedJobs,timeTriggers）
图7-blockedJobs-timeTriggers
图8-RAMJobStore-blockedJobs
- 针对两个内部的数据进行查看比对：果然在blockedJobs的确存在一直没有执行的这个Job，而在timeTriggers中的确是少了Tigger.
- 这时候更加明了了肯定就是这个blockedJobs搞得鬼：看下这个数据结构的操作时机，再次去查看Quartz源码；
- 表示size为9 说明这时候存在9个任务正处于blocked,排除异常还有8个任务此时正处于触发状态。
因为不是解析源码，而是快速定位问题，直接关注调用链更能带来一些便捷：
2.4.1 blockedJobs-methods
图9-Quartz-blockedJobs
blockedJobs容器在整个quartz中的调用并不是很多，这也为我这次定位问题节省不少时间。除了上面的判断是否存在方法（其实到这步有经验的同仁估计已经猜到了，就是上面的判断方法阻断trigger），先快速查看下容器的增加和删除方法使用链。
add:
- add 方法在上面已经分析过，triggersFire方法中，如果是isConcurrentExectionDisallowed 则会将Job放入blockedJobs. 而且整个全局就这一出调用。这更为方便，所以只需找到原因什么时候清除？以及应征了我在2.4.1小节提出的问题1。
remove:
剔除部分代码，通过源码可以很直接的观测到清除逻辑是在triggeredJobComplete方法中进行处理的。而triggeredJobComplete 根据方法名猜到其实就是触发完成后执行
这里简单补充说明下，Quartz几个事件的顺序：
- 1 triggerFired
- 2 jobToBeExecuted
- 3 JobWasExecuted
- 4 triggerComplete
00:44:30.008 [test_Worker-1] INFO org.mzw.quartz.listener.BaseTriggerListener - >>>>>> triggerFired [ j0 ]
00:44:30.010 [test_Worker-1] INFO org.mzw.quartz.listener.BaseTriggerListener - >>>>>> vetoJobExecution [ j0 ]
00:44:30.010 [test_Worker-1] INFO org.mzw.quartz.listener.BaseTriggerListener - >>>>>> jobToBeExecuted [ j0 ]
00:44:30.010 [test_Worker-1] DEBUG org.quartz.core.JobRunShell - Calling execute on job g1.j0
00:44:30.010 [test_Worker-1] INFO org.mzw.quartz.job.BaseJob - -----------execute-------j0-----
00:44:30.010 [test_Worker-1] INFO org.mzw.quartz.listener.BaseTriggerListener - >>>>>> jobWasExecuted [ j0 ]
00:44:30.011 [test_Worker-1] INFO org.mzw.quartz.listener.BaseTriggerListener - >>>>>> triggerComplete [ j0 ]
说以Trigger的生命周期包含整个任务的全部生命周期。理解这点是很重要的。
public void triggeredJobComplete(OperableTrigger trigger,
JobDetail jobDetail, CompletedExecutionInstruction triggerInstCode) {
synchronized (lock) {
JobWrapper jw = jobsByKey.get(jobDetail.getKey());
TriggerWrapper tw = triggersByKey.get(trigger.getKey());
if (jw != null) {
JobDetail jd = jw.jobDetail;
if (jd.isPersistJobDataAfterExecution()) {
...
}
if (jd.isConcurrentExectionDisallowed()) {
blockedJobs.remove(jd.getKey());//清理1
ArrayList<TriggerWrapper> trigs = getTriggerWrappersForJob(jd.getKey());
for(TriggerWrapper ttw : trigs) {
if (ttw.state == TriggerWrapper.STATE_BLOCKED) {
ttw.state = TriggerWrapper.STATE_WAITING;
timeTriggers.add(ttw);//重新载入到timeTriggers
}
if (ttw.state == TriggerWrapper.STATE_PAUSED_BLOCKED) {
ttw.state = TriggerWrapper.STATE_PAUSED;
}
}
signaler.signalSchedulingChange(0L);
}
} else { // even if it was deleted, there may be cleanup to do
blockedJobs.remove(jobDetail.getKey());//清理2
}
...
}
2.4.1 triggeredJobComplete-method
根据图示 这里只需关注标注的两个地方，下面两处是Tigger_ERROR 时调用，根据日志我们并没有提示该信息。所以可以直接忽略。
图10-triggeredJobComplete-stack
上面两处的调用，
protected void notifyJobStoreJobComplete(OperableTrigger trigger, JobDetail detail, CompletedExecutionInstruction instCode) {
resources.getJobStore().triggeredJobComplete(trigger, detail, instCode);
}
protected void notifyJobStoreJobVetoed(OperableTrigger trigger, JobDetail detail, CompletedExecutionInstruction instCode) {
resources.getJobStore().triggeredJobComplete(trigger, detail, instCode);
}
截取第一部分的调用环节，截取需要关注部分的代码，关注我重点标记的代码：
- 重点关注这里 0 ：job.execute(jec) 这个就是我们实现Job的execute方法，发起业务调度的逻辑也是在这里实现的。
- 重点关注这里 1 ：notifyJobListenersComplete(jec, jobExEx): Job的一次调度完成后进行轮询通知所有注册过的JobLinteners. 这里就会回调JobListener的jobWasExecuted方法。
- 重点关注这里 2 ：notifyTriggerListenersComplete(jec, jobExEx)：Job的一次调度完成后进行轮询通知所有注册过的TriggerListener, 并且会回调TriggerListener的triggerComplete（如果配置了匹配器，则通过符合规则的TriggerListener）。
- 重点关注这里 3 ：notifyJobStoreJobComplete 此处显示的调用这次关注的目标方法。所以Quartz的Job的调度流程很明了，所以任务一旦完成就会调用此方法，把Job从blockedJobs中移除。
经过上述分析过程其实就很明了了，别的其他流程都是quartz内部流转，而且在外部干涉的情况可能性几乎为0，只有job.execute(jec)方法再是我们实现了的。所以这里才是我进行关注的重点。排查范围逐步减少。
public void run() {
qs.addInternalSchedulerListener(this);
try {
OperableTrigger trigger = (OperableTrigger) jec.getTrigger();
JobDetail jobDetail = jec.getJobDetail();
do {
JobExecutionException jobExEx = null;
Job job = jec.getJobInstance();
...
// notify job & trigger listeners...
...
long startTime = System.currentTimeMillis();
long endTime = startTime;
// execute the job
try {
log.debug("Calling execute on job " + jobDetail.getKey());
//重点关注这里 0
job.execute(jec);
endTime = System.currentTimeMillis();
} catch (Throwable e) {...qs.notifySchedulerListenersError...}
jec.setJobRunTime(endTime - startTime);
// notify all job listeners
//重点关注这里 1
if (!notifyJobListenersComplete(jec, jobExEx)) {
break;
}
...
// update the trigger
...
// notify all trigger listeners
////重点关注这里 2
if (!notifyTriggerListenersComplete(jec, instCode)) {
break;
}
// update job/trigger or re-execute job
...
//重点关注这里 3
qs.notifyJobStoreJobComplete(trigger, jobDetail, instCode);
break;
} while (true);
} finally {
qs.removeInternalSchedulerListener(this);
}
}
为了证实猜测，做了几次实验，在任务执行的时候中断网络（我们是使用zk作为协调服务，同时在任务执行中作为调度核心流程日志进行入库操作），然后任务就会转移到其它调度服务实例继续执行。
然后我们手动让任务设法再次漂移到事发的调度服务实例上，果然问题继续复现，现象一模一样。也符合之前的猜想。肯定是断网期间发生了一些事情。
这样问题范围缩小，也能复现，所以就切换到本地环境+断电测试。
最终也发现了其中一个问题：
- 由于写日志的代码逻辑没有捕获异常，所以中断了当前线程导致任务一直没有结束。
- 项目持久层框架使用MyBatis，但是并没有设置超时（非连接池，期初认为是druid的超时问题，后经验证并不是），有概率在网络中断长久性阻塞，待网络恢复后报出超时操作异常，从而中断线程。
- 新增的Job并不是能中断之前的Job线程对象,即使我们显示的实现了interuptor方法，因为每个Quartz触发Job时都是通过Class对象反射生成一个新的Job进行调度。
三 问题确认
3.1 暂时主动修复
最终经过之前反复的取证，查找终于判定是我们内部实现出了问题，即上述描述的两个问题。最终确定一个比较关键的事情，尽管Quartz内部可提供自实现的线程池优化了线程调度，但是作为业务执行长时间占用调度线程，导致任务一直得到释放，导致中间过程更容易因诸多外在因素诱发异常从而导致任务永久性的处于阻塞中。
同时两次问题的触发都是由于我们团队针对生产服务的负载人工进行的干预才导致诱发，所以避免再次出现问题，修复也是需要提上日程了。
之后针对调度核心再次做了优化，除了诸多必要的逻辑优化，代码健壮优化，针对调度线程的优化也是必不可少的。
问题找到之后就是所谓的修复...上线...ing。
3.2 Quartz 设计是否存在缺陷
经过测试以及源码验证，的确增加了并发限制的Job如果上次触发生命周期没有结束（不管是出于异常，还是其他原因），blockedJobs队列中的Job不能得到释放，导致该任务不能继续触发，这逻辑似乎设计没问题，
但是，如果调用remove接口，重新添加Job此时也不能执行这就有点说不过去了，作为中间件应该有所考虑，至于为什么没有如此设计，笔者暂时不得而知，或许还得和Quartz官方交流后才能得到答案，目前只能从我们这边进行修复这个问题，当然也并不是很难。
四 总结
诱因存在几个，但的确并不是很复杂，出现的原因也是代码质量以及代码审核出现漏洞，尤其像这种一旦出现问题，现场很少能提供给你定位信息，所以规范代码很重要。
网友评论