最近遇到一个Spring定时任务没有及时启动,经常过30分钟以上才执行。最后定位原因,是因为所有的Spring定时任务共用同一个线程,如果有一个线程耗时太长,会导致后续定时任务阻塞。
好奇怪
排查问题,发现定时器设置正确(每分钟执行一次),而且在任务的第一行就输出日志。
@Scheduled(fixedRate = 60 * 1000)
[2019-01-10 18:13:56.913][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 18:13:56.938][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 18:38:49.103][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 18:38:49.119][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 19:02:40.755][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 19:02:40.770][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 19:29:02.527][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 19:29:02.551][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 19:56:53.597][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 19:56:53.615][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 20:24:05.241][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 20:24:05.262][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 20:39:22.504][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 21:22:02.099][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 21:22:02.116][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 21:48:19.265][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 21:48:19.277][pool-6-thread-1][INFO][Crontab:91][][]: start to run task crontab
日志显示,一般过了20~30分钟,会连续执行两次任务。
看起来是Spring定时任务出错了,感觉有点崩溃,不能相信Spring会出现这么简单的错误。但是事实又这么明显
再思考
- 从日志来看,执行定时任务的线程名是
pool-6-thread-1
,属于某一个线程池。那么可能是线程池的线程数不够,那么找到这个线程之前在做的事情就知道为什么这个线程一直没来执行定时任务
执行命令:
grep pool-6-thread-1 all.log
果然找到问题,原来
pool-6-thread-1
线程在执行另外一个耗时很长的任务
问题定位
Spring定时任务默认使用的SingleThreadScheduledExecutor
,所有任务共用一个线程,所以会互相等待。
protected void scheduleTasks() {
if (this.taskScheduler == null) {
//使用的是SingleThreadScheduledExecutor(只有一个线程)
this.localExecutor = Executors.newSingleThreadScheduledExecutor();
this.taskScheduler = new ConcurrentTaskScheduler(this.localExecutor);
}
if (this.triggerTasks != null) {
for (TriggerTask task : this.triggerTasks) {
addScheduledTask(scheduleTriggerTask(task));
}
}
if (this.cronTasks != null) {
for (CronTask task : this.cronTasks) {
addScheduledTask(scheduleCronTask(task));
}
}
if (this.fixedRateTasks != null) {
for (IntervalTask task : this.fixedRateTasks) {
addScheduledTask(scheduleFixedRateTask(task));
}
}
if (this.fixedDelayTasks != null) {
for (IntervalTask task : this.fixedDelayTasks) {
addScheduledTask(scheduleFixedDelayTask(task));
}
}
}
解决办法
最简单的办法就是减少定时任务耗时,但是本文还介绍另外一种
自定义定时任务线程池,实现方式如下:
- 增加两个注解:
@EnableAsync
和@Async
@EnableScheduling
@EnableAsync
public class Crontab {
@Scheduled(fixedRate = 60)
@Async
public void doTask() {
log.info("start to run task crontab");
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
- 配置线程池
<task:annotation-driven scheduler="crontab-scheduler"/>
<task:scheduler id="crontab-scheduler" pool-size="10"/>
- 运行结果
[2019-01-10 22:31:24.120][crontab-scheduler-3][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.180][crontab-scheduler-2][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.240][crontab-scheduler-4][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.300][crontab-scheduler-7][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.360][crontab-scheduler-6][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.420][crontab-scheduler-5][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.480][crontab-scheduler-9][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.540][crontab-scheduler-10][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:24.600][crontab-scheduler-8][INFO][Crontab:91][][]: start to run task crontab
[2019-01-10 22:31:34.100][crontab-scheduler-1][INFO][Crontab:91][][]: start to run task crontab
日志可以看出来,定时任务使用了10个线程
最佳实践
- 定时任务不能执行耗时任务,阻塞其他任务的执行
- 可以使用自定义线程池