What causes Spring scheduler to execute before the application and servlet starts up?

Question

I have a simple Spring-Boot web application with some scheduling tasks:

@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);
    }
}

And a service executing two scheduling tasks:

@Service
public class SchedulingService {

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

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

Is there any explanation revealing why one of the scheduling tasks has been executed before the application and servlet starts up? This happens repeatedly and the log order is always the same, so I suspect the multithreading doesn't take place - there is nearly one-second difference between the first and the second scheduling task.

Here is the log with highlighted parts of the scheduling task log:

2018-08-18 20:47:53.085 INFO 251168 --- [ost-startStop-1] o.s.b.a.w.s.WelcomePageHandlerMapping : Adding welcome page template: index

2018-08-18 20:47:53.300 INFO 251168 --- [ost-startStop-1] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup

2018-08-18 20:47:53.314 INFO 251168 --- [ost-startStop-1] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing

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 : Started Application in 5.565 seconds (JVM running for 16.93)

2018-08-18 20:47:53.396 INFO 251168 --- [ main] org.apache.coyote.ajp.AjpNioProtocol : Starting ProtocolHandler ["ajp-nio-8009"]

2018-08-18 20:47:53.400 INFO 251168 --- [ main] org.apache.catalina.startup.Catalina : Server startup in 15970 ms

2018-08-18 20:47:53.477 INFO 251168 --- [nio-8080-exec-1] o.a.c.c.C.[.[localhost].[/Rattle] : Initializing Spring FrameworkServlet 'dispatcherServlet'

2018-08-18 20:47:53.477 INFO 251168 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started

2018-08-18 20:47:53.520 INFO 251168 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 43 ms

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

If all its dependencies are satisfied the bean is created. As there is no delay, the task runs immediately. Why would it wait for startup if you didn't tell it to? — Boris the Spider
@BoristheSpider: I wonder if the scheduling task can be executed before the Spring application starts itself: my.appname.Application : Started Application in 5.565 seconds. Isn't the scheduling bean dependant on the application start. Or do I understand this log wrong or miss something? — Nikolas Charalambidis
@BoristheSpider how to tell it to wait until the application starts up ? Sorry for commenting on old question. — Amir Choubani

Alex Roig Alex Roig · Accepted Answer · 2018-08-18T19:37:43

I just created an empty SpringBoot project, added your class and tried to reproduce the same issue. On SpringBoot 2.0.4.RELEASE I see that both tasks run at the same time and same thread:

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

Then, I added a Thread.sleep(100) on the both tasks as I cannot predict the execution order.

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

The delay of aprox 100ms between the log entries, confirm that they run on the same thread.

You might think that setting the initialDelay = 0 on the @Scheduled might help, but it will not; everything will still be on the main thread.

The solution I found is defining a custom bean that creates a customTaskScheduler:

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

Now, the logs show that both tasks are executed at the same time and by different threads:

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

I defined a thread pool of size = 2. What will happen if I have 3 tasks to run? One of the tasks will need to wait to complete the execution of the previous 2, get the thread released and check the execution queue again.

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

What causes Spring scheduler to execute before the application and servlet starts up?

2 Answers