时间戳

首页 > 解决方案 > 是什么导致 Spring 调度程序在应用程序和 servlet 启动之前执行？

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

问题描述

我有一个简单的 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：找不到用于计划处理的 TaskScheduler/ScheduledExecutorService bean

2018-08-18 20:47:53.321 HERE LOGGED FIRST

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 --- [main] org.apache.catalina.startup.Catalina：服务器启动时间为 15970 毫秒

2018-08-18 20:47:53.477 INFO 251168 --- [nio-8080-exec-1] oaccC[.[localhost].[/Rattle]：初始化 Spring FrameworkServlet '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 HERE LOGGED SECOND

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

标签： javaspringspring-bootscheduled-tasks

解决方案

我刚刚创建了一个空的 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

日志条目之间的延迟大约 100 毫秒，确认它们在同一线程上运行。

您可能认为将 设置为initialDelay = 0on@Scheduled可能会有所帮助，但它不会；一切仍将在主线程上。

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

@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 个任务要运行，会发生什么？其中一项任务需要等待完成前两项的执行，释放线程并再次检查执行队列。

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

推荐阅读