问题
每日0点统计商家前一天订单数量,销售额。发现统计表出现两份数据,一份在0点生成,一份在00:05生成。
分析
2018-07-18 17:06:00.002 ERROR 1064 --- [pool-2-thread-1] isticJob$$EnhancerBySpringCGLIB$$f68d4cc : 开始StatisticJob》》》》》》》》》》》》》》
2018-7-18 17:06:00setScheduler
2018-7-18 17:06:00success=true
2018-07-18 17:06:00.105 INFO 1064 --- [pool-2-thread-1] c.u.core.interceptor.MybatisInterceptor : com.ukingclub.food.dao.statistic.IStatisticFoodDao.statisticDay
执行SQL:CALL pro_statistic_day_food('2018-07-03');
执行时间:30ms
2018-07-18 17:06:00.109 INFO 1064 --- [pool-2-thread-1] c.u.core.aspect.ServiceLogAspect : 执行service方法:class com.ukingclub.food.service.statistic.StatisticFoodService.statisticDay() 本次共耗时:[52毫秒]
2018-07-18 17:06:00.109 INFO 1064 --- [pool-2-thread-1] isticJob$$EnhancerBySpringCGLIB$$f68d4cc : 订单数据分析任务结束,统计耗时:0秒
2018-07-18 17:11:00.109 ERROR 1064 --- [pool-2-thread-1] isticJob$$EnhancerBySpringCGLIB$$f68d4cc : 结束StatisticJob》》》》》》》》》》》》》》
2018-07-18 17:11:00.116 ERROR 1064 --- [pool-2-thread-1] ticJob2$$EnhancerBySpringCGLIB$$bf08f5b4 : 开始StatisticJob2》》》》》》》》》》》》》》
2018-7-18 17:11:00setScheduler
2018-7-18 17:11:00success=true
2018-07-18 17:11:00.136 INFO 1064 --- [pool-2-thread-1] c.u.core.interceptor.MybatisInterceptor : com.ukingclub.food.dao.statistic.IStatisticFoodDao.statisticDay
执行SQL:CALL pro_statistic_day_food('2018-07-03');
执行时间:17ms
2018-07-18 17:11:00.137 INFO 1064 --- [pool-2-thread-1] c.u.core.aspect.ServiceLogAspect : 执行service方法:class com.ukingclub.food.service.statistic.StatisticFoodService.statisticDay() 本次共耗时:[18毫秒]
2018-07-18 17:11:00.138 INFO 1064 --- [pool-2-thread-1] ticJob2$$EnhancerBySpringCGLIB$$bf08f5b4 : 订单数据分析任务结束,统计耗时=====:0秒
2018-07-18 17:16:00.139 ERROR 1064 --- [pool-2-thread-1] ticJob2$$EnhancerBySpringCGLIB$$bf08f5b4 : 结束StatisticJob2》》》》》》》》》》》》》》
- 怀疑Job没有通知执行,网上查了一下,果然是少配置了注解,Job只能同步执行。
- 但是两台服务器为啥也会出现同一个Job执行了两次?有锁控制了啊,原来是0点有多个任务同时执行,所有总会有一个商家统计Job会晚5分钟执行。因为Job一般执行后会睡5分钟。
处理方案
Job类增加注解:@EnableAsync
方法增加注解:@Async
参考:SpringBoot + @Scheduled 多任务并发
总结
- 查看线程执行时机,判断问题出现在哪里