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

Question

我有一个简单的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启动之前执行了其中一个调度任务？这种情况反复发生，日志顺序总是相同的，所以我怀疑多线程没有发生--第一个调度任务和第二个调度任务之间有将近一秒的差异。

2018-08-18 20:47:53.085信息251168--[ost-startStop-1]O.S.B.A.W.S.WelcomePageHandlerMapping：添加欢迎页面模板：索引

2018-08-18 20:47:53.300信息251168--[ost-startStop-1]O.S.J.E.A.AnnotationMBeanExporter：在启动时为JMX公开注册bean

2018-08-18 20:47:53.314信息251168--[ost-startStop-1]S.A.ScheduleDanNotationBeanPostProcessor：找不到用于计划处理的TaskScheduler/ScheduleDexecutorService bean

2018-08-18 20:47:53.321此处首次登录

2018-08-18 20:47:53.344信息251168--[ost-startStop-1]my.appname.Application：5.565秒启动应用程序（JVM运行16.93）

2018-08-18 20:47:53.396信息251168---[main]org.apache.coyote.ajp.ajpnioprotocol：启动协议处理程序[“ajp-nio-8009”]

2018-08-18 20:47:53.400信息251168---[main]org.apache.catalina.startup.catalina：服务器启动15970 ms

2018-08-18 20:47:53.477信息251168---[nio-8080-exec-1]O.A.C.C.C.[.[localhost].[/rattle]:正在初始化Spring FrameworkServlet“Dispatcher Servlet”

2018-08-18 20:47:53.477信息251168--[nio-8080-exec-1]o.s.web.servlet.DispatcherServlet：FrameworkServlet“Dispatcher Servlet”：初始化已启动

2018-08-18 20:47:53.520信息251168--[nio-8080-exec-1]o.s.web.servlet.DispatcherServlet：FrameworkServlet“Dispatcher Servlet”：初始化在43毫秒内完成

2018-08-18 20:47:54.103此处登录秒

2018-08-18 20:47:59.335此处登录秒

2018-08-18 20:48:08.334此处首次登录

Answer 1

我只是创建了一个空的SpringBoot项目，添加了您的类，并尝试重现相同的问题。在SpringBoot2.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，确认它们运行在同一线程上。

我找到的解决方案是定义一个自定义bean，该自定义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个任务要运行，会发生什么？其中一个任务将需要等待完成前面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