首页 文章

是什么导致Spring调度程序在应用程序和servlet启动之前执行?

提问于
浏览
2

我有一个简单的Spring-Boot Web应用程序,其中包含一些调度任务:

@SpringBootApplication
@EnableScheduling
public class Application extends SpringBootServletInitializer {

    @Override
    protected SpringApplicationBuilder configure(final SpringApplicationBuilder app) {
        return app.sources(Application.class);
    }

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }
}

并且服务执行两个调度任务:

@Service
public class SchedulingService {

    @Scheduled(fixedRate = 15000)
    private void first() {
        // log first
    }

    @Scheduled(fixedRate = 6000)
    public void second() {
        // log second
    }
}

是否有任何解释揭示为什么在应用程序和servlet启动之前已执行其中一个调度任务?这种情况反复发生,并且日志顺序始终相同,因此我怀疑多线程不会发生 - 第一个和第二个调度任务之间差异接近一秒 .

这是 highlighted parts of the scheduling task log 的日志:

2018-08-18 20:47:53.085 INFO 251168 --- [ost-startStop-1] osbawsWelcomePageHandlerMapping:添加欢迎页面模板:索引2018-08-18 20:47:53.300 INFO 251168 --- [ost- startStop-1] osjeaAnnotationMBeanExporter:在启动时为JMX暴露注册bean 2018-08-18 20:47:53.314 INFO 251168 --- [ost-startStop-1] saScheduledAnnotationBeanPostProcessor:找不到用于调度处理2018的TaskScheduler / ScheduledExecutorService bean- 08-18 20:47:53.321首先记录2018-08-18 20:47:53.344 INFO 251168 --- [ost-startStop-1] my.appname.Application:在5.565秒内启动应用程序(JVM运行16.93) 2018-08-18 20:47:53.396 INFO 251168 --- [main] org.apache.coyote.ajp.AjpNioProtocol:启动ProtocolHandler [“ajp-nio-8009”] 2018-08-18 20:47:53.400 INFO 251168 --- [主要] org.apache.catalina.startup.Catalina:服务器启动时间为15970 ms 2018-08-18 20:47:53.477 INFO 251168 --- [nio-8080-exec-1] oaccC [ . [ localhost] . [/ Rattle]:初始化Spring Fr. ameworkServlet'dispatcherServlet'2018-08-18 20:47:53.477 INFO 251168 --- [nio-8080-exec-1] osweb.servlet.DispatcherServlet:FrameworkServlet'dispatcherServlet':初始化开始2018-08-18 20:47 :53.520 INFO 251168 --- [nio-8080-exec-1] osweb.servlet.DispatcherServlet:FrameworkServlet'dispatcherServlet':初始化完成时间为43毫秒2018-08-18 20:47:54.103此处记录第二个2018-08- 18 20:47:59.335 HERE LOGGED SECOND 2018-08-18 20:48:05.334 HERE LOGGED SECOND 2018-08-18 20:48:08.334 HERE LOGGED FIRST

1 回答

  • 3

    我刚刚创建了一个空的SpringBoot项目,添加了你的类并尝试重现同样的问题 . 在SpringBoot上 2.0.4.RELEASE 我看到两个任务同时运行并且同一个线程:

    2018-08-18 21:16:54.145  INFO 10239 --- [pool-1-thread-1] com.test.SchedulingService               : LOG FIRST
    2018-08-18 21:16:54.145  INFO 10239 --- [pool-1-thread-1] com.test.SchedulingService               : LOG SECOND
    

    然后,我在这两个任务上添加了 Thread.sleep(100) ,因为我无法预测执行顺序 .

    2018-08-18 21:21:14.775  INFO 10274 --- [pool-1-thread-1] com.test.SchedulingService               : LOG FIRST
    2018-08-18 21:21:14.878  INFO 10274 --- [pool-1-thread-1] com.test.SchedulingService               : LOG SECOND
    

    日志条目之间的aprox延迟100ms,确认它们在同一个线程上运行 .

    您可能认为在 @Scheduled 上设置 initialDelay = 0 可能有所帮助,但它不会;一切都仍然在主线上 .

    我找到的解决方案是定义一个创建 customTaskScheduler 的自定义bean:

    @Bean()
    public  ThreadPoolTaskScheduler  taskScheduler(){
        ThreadPoolTaskScheduler taskScheduler = new ThreadPoolTaskScheduler();
        taskScheduler.setPoolSize(2);
        taskScheduler.setThreadNamePrefix("Async-");
        return  taskScheduler;
    }
    

    现在,日志显示两个任务同时由不同的线程执行:

    2018-08-18 21:30:26.482  INFO 10383 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
    2018-08-18 21:30:26.486  INFO 10383 --- [           main] com.test.ProjectApplication              : Started ProjectApplication in 1.767 seconds (JVM running for 2.137)
    2018-08-18 21:30:26.555  INFO 10383 --- [        Async-2] com.test.SchedulingService               : LOG SECOND
    2018-08-18 21:30:26.555  INFO 10383 --- [        Async-1] com.test.SchedulingService               : LOG FIRST
    

    我定义了一个 size = 2 的线程池 . 如果我要运行3个任务会发生什么?其中一个任务需要等待完成前一个2的执行,释放线程并再次检查执行队列 .

    2018-08-18 21:33:48.895  INFO 10412 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
    2018-08-18 21:33:48.899  INFO 10412 --- [           main] com.test.ProjectApplication              : Started ProjectApplication in 1.888 seconds (JVM running for 2.258)
    2018-08-18 21:33:48.960  INFO 10412 --- [        Async-1] com.test.SchedulingService               : LOG FIRST
    2018-08-18 21:33:48.960  INFO 10412 --- [        Async-2] com.test.SchedulingService               : LOG SECOND
    2018-08-18 21:33:49.065  INFO 10412 --- [        Async-2] com.test.SchedulingService               : LOG THIRD
    

相关问题