开启掘金成长之旅！这是我参与「掘金日新计划 · 12 月更文挑战」的第4天，点击查看活动详情
问题发现
前段时间修改了一个小应用多节点定时任务重复执行的问题，以为再也不用关心了。发布到uat之后就没有在关注。这两天想起来，就去查了一下两个节点的日志，发现一个基于cron表达式(0 0 5 ? * *) 每天5点执行一次的任务，居然在两个节点都有日志打印。
定位问题
任务相关代码大体如下，省略了具体实现：
@SchedulerLock(name = "TaskScheduler_bitMapAllTask", lockAtLeastFor = "3s")
@Scheduled(cron = "0 0 5 ? * *")
public void dbTask() {
// db 查询
log.info(" update log ")
}
从代码可以看出，已经借助了SchedulerLock注解帮我们实现分布式锁的功能，也就意味着正常情况下在5点的时候当前任务只会在一个节点执行。难道是使用方式有问题，但是有几个小时级别的任务确实是分散到不同节点去执行的。这就很奇怪了，于是仔细看了看日志，终于有了一点眉目：
节点1：
kubectl logs -f -n node1 |grep " update log "
2022-12-01 05:00:56.470 INFO [app-engine,,] - [scheduling-1] i.t.c.t.e.schedule.ServiceByDaySchedule : update log
节点2：
kubectl logs -f -n node2 |grep " update log "
2022-12-01 05:00:00.060 INFO [app-engine,,] - [scheduling-1] i.t.c.t.e.schedule.ServiceByDaySchedule : update log
通过日志可以看到，节点2是在 05:00:00执行了任务，节点1是在05:00:56执行的任务。此时可以推测节点2上的任务应该是在等待前面的任务完成，并且持续了50多秒。
查阅了一下Spring 定时任务的默认的调度线程大小是1。于是往上多看了几行日志
2022-12-01 05:00:55.949 INFO [app-engine,,] - [scheduling-1] i.t.c.t.e.s.c.CallBack : query xxx
发现确实调度线程scheduling-1在执行其他任务。
这样也就可以判断为什么shedlock的分布式锁会失效了：
当05:00:00这个时刻，定时任务启动，实际上两个节点都执行了对应的方法。一个节点加锁并且执行完成之后，更新了shedlock锁的时间，(大家可以直接去shedlock表中查看)：
lockAt：2022-12-01 05:00:50.445
lockUtil：2022-12-01 05:00:53.437
另一个节点还在等调度线程执行其他的调度任务。并且任务执行耗时已经超过了当前任务锁的最大时间lockUtil，于是当调度线程执行到我们定时任务方法的时候，会发先其可以获取到锁，并且更新了锁时间为：
lockAt：2022-12-01 05:00:56.445
lockUtil：2022-12-01 05:00:59.437
复现问题
这里我创建了两个定时任务，为了快速复现，定时任务时间分别是每分钟第10s和每分钟第30s执行。并且10s的任务会暂停40s，目的就是为了让锁超时。
@Slf4j
@Component
public class ApiScheduleTask {
/**
* 最少持有时间, unlock的时候会更新。开始的时候是配置的最大持有时间:defaultLockAtMostFor = "PT30S"
*/
@SchedulerLock(name = "TestTaskScheduler", lockAtLeastFor = "3s")
@Scheduled(cron = "10 * * * * ?")
public void testSchedule() {
log.info("test task");
try {
Thread.sleep(40000);
} catch (InterruptedException interruptedException) {
interruptedException.printStackTrace();
}
log.info("test task end");
}
@SchedulerLock(name = "TestTaskScheduler21", lockAtLeastFor = "3s")
@Scheduled(cron = "30 * * * * ?")
public void test2Schedule() {
log.info("test2task");
log.info("test2 task end");
}
}
启动两个application查看运行结果：
application01
2022-12-01 15:42:10.222 INFO 43102 --- [ scheduling-1] sys.tag.api.schedule.ApiScheduleTask : test task
2022-12-01 15:42:50.225 INFO 43102 --- [ scheduling-1] sys.tag.api.schedule.ApiScheduleTask : test task end
2022-12-01 15:42:50.416 INFO 43102 --- [ scheduling-1] sys.tag.api.schedule.ApiScheduleTask : test2task
2022-12-01 15:42:50.416 INFO 43102 --- [ scheduling-1] sys.tag.api.schedule.ApiScheduleTask : test2 task end
application02
2022-12-01 15:42:30.193 INFO 43215 --- [ scheduling-1] sys.tag.api.schedule.ApiScheduleTask : test2task
2022-12-01 15:42:30.193 INFO 43215 --- [ scheduling-1] sys.tag.api.schedule.ApiScheduleTask : test2 task end
会发现一分钟内，任务1只在一个节点执行了，但是任务2确在两个节点都执行了。
如果你去查看shedlock表中数据的变化，就会发现和我们上面分析的基本一致。问题原因也就是因为第二个任务被线程调度的时候也可以获取到锁了。
解决方式
知道了问题，那么就可以进行解决了。这里采用了最简单的方式进行解决，修改其调度的线程池大小：
spring:
task:
scheduling:
pool:
size: 2
此时，在重新运行上面的上面的两个任务进行测试，会发现问题已经解决。
总结
有时候一些老的项目，使用一些不熟悉的框架去修复问题之后，还是需要多多自测。并且及时观察修改后的效果。像这种因为任务执行耗时较久的情况，在本地自测的时候是很难复现。
