前言
项目中使用了 quartz 来支持定时任务的相关基础支撑, 但是 最近添加了一个 资源消耗比较高的定时任务, 发布到测试环境之后, 发现服务突然 起不起来了[资源比较有限]
然后 查看了一下日志, 这个定时任务怎么在执行?, 不是 配置的是 凌晨两点么, 然后 仔细一看 几乎配置的 七八个定时任务都跑了一次, 只是 可能其他的任务开销比较小, 平时没有怎么注意
呵呵 然后 这里就是关注这个问题, 项目启动之后 所有的定时任务 自动跑了一次
然后 在调试的过程中会发现 qrtz_triggers 会进行 多次的更新, 这些更新或许会是本文的一些核心收货之一
备注 : 一下测试任务为1小时执行一次, 以下截图中的 fireTime 不为整点的均视为当前时间[多次调试]
定时任务的 Executor 启动执行
从这里可以看到 trigger 的 previousFireTime 是项目启动的时间, nextFireTime 是基于 previousFireTime 以及 cron 计算的下一次需要执行的时间
这里的 previousFireTime 指的就是当前这一次定时任务的触发, 那么 这个时间 是怎么来的呢?
顺便查询一下 该任务对应的数据库的记录, 是和 业务代码中获取的配置是保持一致的, 那么是哪里的代码 修改的 qrtz_triggers 呢?, 这里或许会找到一些线索
更新 qrtz_trigger 的 fire_time 的地方
找了一下 postgres 的日志, 呵呵 发现更新 qrtz_trigger 的 sql 大致如下, 将 nextFireTime 更新为 null, previousFireTime 更新为了 当时时间
2020-12-21 03:40:36.663 TIME,"postgres","dcams",2724,"172.18.0.1:39966",5fe017db.aa4,7,"UPDATE",2020-12-21 03:34:51 TIME,7/1626,1159546,LOG,00000,"execute <unnamed>: UPDATE QRTZ_TRIGGERS SET JOB_NAME = $1, JOB_GROUP = $2, DESCRIPTION = $3, NEXT_FIRE_TIME = $4, PREV_FIRE_TIME = $5, TRIGGER_STATE = $6, TRIGGER_TYPE = $7, START_TIME = $8, END_TIME = $9, CALENDAR_NAME = $10, MISFIRE_INSTR = $11, PRIORITY = $12 WHERE SCHED_NAME = ''quartzScheduler'' AND TRIGGER_NAME = $13 AND TRIGGER_GROUP = $14","parameters: $1 = ''HOME_OVERVIEW'', $2 = ''DEFAULT'', $3 = NULL, $4 = ''1608522036590'', $5 = ''-1'', $6 = ''WAITING'', $7 = ''CRON'', $8 = ''1600052000000'', $9 = ''0'', $10 = NULL, $11 = ''0'', $12 = ''5'', $13 = ''HOME_OVERVIEW'', $14 = ''DEFAULT''",,,,,,,,"PostgreSQL JDBC Driver"
2020-12-21 03:40:36.667 TIME,"postgres","dcams",2724,"172.18.0.1:39966",5fe017db.aa4,8,"UPDATE",2020-12-21 03:34:51 TIME,7/1626,1159546,LOG,00000,"execute <unnamed>: UPDATE QRTZ_CRON_TRIGGERS SET CRON_EXPRESSION = $1, TIME_ZONE_ID = $2 WHERE SCHED_NAME = ''quartzScheduler'' AND TRIGGER_NAME = $3 AND TRIGGER_GROUP = $4","parameters: $1 = ''0 0 0/1 * * ?'', $2 = ''Asia/Shanghai'', $3 = ''HOME_OVERVIEW'', $4 = ''DEFAULT''",,,,,,,,"PostgreSQL JDBC Driver"
根据上面的 update sql, 我们找一下 其在代码中的位置
然后定位一下使用的地方 打上断点, 呵呵 果然就来了
经过调试发现, trigger 的 nextFireTime 更新为当前时间是在 trig. updateAfterMisfire, 呵呵 这个我们后面再看
我们先看一些 能够推进事情继续往下走的东西
我们来看一下 更新 trigger nextFireTime 更新为当前时间之前的一些情况, 呵呵 这里的 nextFireTime 是 2020.09.14 11:00?, 从时间上来推测 大概可以推测是根据 startTime 计算的下一次触发的时间[我们稍后会有具体的代码的体现]
顺便查询一下 该任务对应的数据库的记录, 是和 这里业务代码中获取的配置是保持一致的, 那么是哪里的代码 修改的 qrtz_triggers 呢?, 这里或许会找到一些线索
下一个坑先挖在这里了[上一次更新 qrtz_trigger 的 fire_time 的地方], 我们接下来先填现在的这个坑
看一下 CronTrigger 对于 misfire 的任务的处理, 有几种策略, 我们这里的情况是 默认的 SMART_POLICY, 这里转换为了 立即触发一次
1. 忽略 就直接退出了, fireTime 相关不变
2. doNothing 是啥都不做, 但是根据当前时间重新计算一下 下一次触发的时间
3. 立即触发一次, 是更新下一次触发时间为当前时间
这里可以看到 nextFireTime 更新成了当前时间, 但是在上一个阶段我们看到的结果是 previousFireTime 是当前时间, nextFireTime 是根据当前时间计算的下一个触发时间点, 是怎么回事呢 ?
上面吧 nextFireTime 更新成当前时间, 接着会触发一次当前任务的执行, 下面的地方 会更新 qrtz_trigger, switch 一下, trigger.triggered(cal) 会根据当前这次触发的时间计算下一次的触发时间, 并将 previousFireTime 更新为这一次的触发时间
下面的 qrtz_trigger 的更新 还是走的是上面的更新的方法, 相同的 sql
上一次更新 qrtz_trigger 的 fire_time 的地方
假设我项目上一次关闭的时候 qrtz_trigger HOME_OVERVIEW 的 nextFireTime 和 previousFireTime 分别为 2020.12.26 15:00 和 2020.12.26 16:00
那么 qrtz_trigger 是怎么被更新成 nextFireTime 是 2020.09.14 11:00 的呢? spring-quartz 是怎么做到 每一次重启都会重新执行一次 定时任务的呢 ?
因为 如果我是在 2020.12.26 15:20 重启, 那么按照上面的配置, 我们的这个任务 应该是不属于 misfire 的情况, 应该是不会走 misfire 的处理[上面的 fire_once_now]
但是这里又会有一个疑问, 当时是在我的立场上面, 既然 qrtz_trigger 在上面的 "更新 qrtz_trigger 的 fire_time 的地方" 之前就被更新了?, 那么我上面的断点为什么第一次进来的时候 nextFireTime 为当前时间呢?, 不应该是为 2020.09.14 11:00 么?
1. 说明还有这个sql还有其他地方使用到[我的立场上面我是看过, 打过断点的, 我是可以否定]
2. 说明还有其他的 sql 会更新 qrtz_trigger, 呵呵 继续 track 一下 sql
还是在我上面的 "更新 qrtz_trigger 的 fire_time 的地方" 断点上, 然后找一下 postgres 日志, 呵呵 找一下 这部分将 qrtz_trigger 的 nextFireTime 更新成 2020.09.14 11:00 的地方, 呵呵 找到了, 原来是先删除了, 然后 在添加进去的阿
22020-12-21 05:48:02.294 TIME,"postgres","dcams",2925,"172.18.0.1:40038",5fe036fc.b6d,35,"DELETE",2020-12-21 05:47:40 TIME,7/1668,1159558,LOG,00000,"execute S_23: DELETE FROM QRTZ_TRIGGERS WHERE SCHED_NAME = ''quartzScheduler'' AND TRIGGER_NAME = $1 AND TRIGGER_GROUP = $2","parameters: $1 = ''HOME_OVERVIEW'', $2 = ''DEFAULT''",,,,,,,,"PostgreSQL JDBC Driver"
2020-12-21 05:48:02.325 TIME,"postgres","dcams",2925,"172.18.0.1:40038",5fe036fc.b6d,36,"INSERT",2020-12-21 05:47:40 TIME,7/1668,1159558,LOG,00000,"execute S_25: INSERT INTO QRTZ_TRIGGERS (SCHED_NAME, TRIGGER_NAME, TRIGGER_GROUP, JOB_NAME, JOB_GROUP, DESCRIPTION, NEXT_FIRE_TIME, PREV_FIRE_TIME, TRIGGER_STATE, TRIGGER_TYPE, START_TIME, END_TIME, CALENDAR_NAME, MISFIRE_INSTR, JOB_DATA, PRIORITY) VALUES(''quartzScheduler'', $1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15)","parameters: $1 = ''HOME_OVERVIEW'', $2 = ''DEFAULT'', $3 = ''HOME_OVERVIEW'', $4 = ''DEFAULT'', $5 = NULL, $6 = ''1600052400000'', $7 = ''-1'', $8 = ''WAITING'', $9 = ''CRON'', $10 = ''1600052000000'', $11 = ''0'', $12 = NULL, $13 = ''0'', $14 = ''\x'', $15 = ''5''",,,,,,,,"PostgreSQL JDBC Driver"
然后我们在 INSERT_TRIGGER 使用的地方来上一个断点, 呵呵 看到了 nextFireTime 计算为 2020.09.14 11:00, 并且即将插入到数据库的场景了
我们看一下具体的更新 trigger 的 fireTime 的地方, 呵呵 在如下代码 trig.computeFirstFireTime(cal)
可以看到的是 newTrigger 是给 Scheduler 这边传入的 trigger, oldTrigger 看这里的情况应该是直接从数据库又查询了一次, 得到的 trigger 的状态
可以看到大致的情况是 项目启动的时候会将各个任务添加到 Scheduler, 然后这里会根据各个任务的 startTime 重新计算 nextFireTime, 然后 替换掉数据库中已有的 qrtz_trigger[启动项目之前已经存在的 qrtz_trigger], 然后后面的 misfire 补偿检测到了 这个任务属于 misfire 的任务, 然后根据策略进行处理, 策略为 SMART_POLICY, 实际的实现中等价于 FIRE_ONCE_NOW, 立即触发了一次
computeFirstFireTime 的方式, 呵呵 根据 startTime 进行的计算
查看一下当前的 qrtz_trigger 的状态
所以, 到这里 你明白了这一系列的 qrtz_trigger 的转换了么?
解决问题
更新一下外部传入给 Scheduler. rescheduleJob(TriggerKey triggerKey, Trigger newTrigger) 传入的 newTrigger 的 misfireInstruction, 更新为 doNothing 即可
完
