Scheduling in Spring: @Schedule and @EnableScheduling lead to multiple calls of method

Question

I have a service which has to run a job to get and refresh it's data from another service. The job has to be run on startup and every couple of hours/days. I was looking into the behavior of the scheduled job and it seems to be called two times consecutively according to the logs (see below).

@Service
public class ServiceImpl implements ServiceInterface {

@Autowired
private FetchService fetchService;

private int timesCalled = 0;
private Data data;

@PostConstruct
private void initialize() {
    data = fetchService.getAndUpdate();
}

@Scheduled(cron = "* */5 * * * *")
private void refresh() {
    LOG.info(appContext.getId());
    LOG.info("This object: " + System.identityHashCode(this));
    LOG.info("Times called: " +  timesCalled);
    timesCalled++;
    data = fetchService.getAndUpdate();
}
...

Here also the logs where the refresh method is being called every 5 minutes, as can be seen it is being called two times:

2020-07-02 17:30:00.006  INFO 30416 --- [   scheduling-1] c.d.p.d.service.ServiceImpl  : org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@6db9cae5
2020-07-02 17:30:00.006  INFO 30416 --- [   scheduling-1] c.d.p.d.serice.ServiceImpl  : This object: 357813323
2020-07-02 17:30:00.006  INFO 30416 --- [   scheduling-1] c.d.p.d.service.ServiceImpl  : Times called: 1
....
2020-07-02 17:30:32.001  INFO 30416 --- [   scheduling-1] c.d.p.d.service.ServiceImpl  : org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@6db9cae5
2020-07-02 17:30:32.001  INFO 30416 --- [   scheduling-1] c.d.p.d.service.ServiceImpl  : This object: 357813323
2020-07-02 17:30:32.001  INFO 30416 --- [   scheduling-1] c.d.p.d.service.ServiceImpl  : Times called: 2

I don't have a web.xml and am using only defaults. I have used the @EnableScheduling tag at root level:

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

I looked into similar questions but couldn't find anything which could help me to find the source of this bug. Any help is appreciated :)

Answer 1

The Behaviour you describe is normal and intended.

As you wrote, your cron expression is * */5 * * * *, which means, according to the Spring guide, that it will run every second of every 5th minute:

A cron-like expression, extending the usual UN*X definition to include triggers on the second, minute, hour, day of month, month, and day of week.

For example, {@code "0 * * * * MON-FRI"} means once per minute on weekdays (at the top of the minute - the 0th second). The fields read from left to right are interpreted as follows.

• second
• minute
• hour
• day of month
• month
• day of week

That can be easily reproduced by taking your code and the cron expression:

@Scheduled(cron = "* */5 * * * *")
private void refresh() {
    log.info("Times called: " +  timesCalled);
    timesCalled++;
}

And observe its behaviour:

14:20:13.001  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 13
14:20:14.001  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 14
14:20:15.003  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 15
14:20:59.002  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 59
14:25:00.000  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 60
14:25:01.000  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 61
14:25:02.001  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 62
14:25:03.002  INFO 8980 --- [   sch-1] com.example.demo.Sched   : Times called: 63

As you see it runs every second, until the minute ends. Than waits till 14:25 and runs again for every second.

But why does it only run 2 times at the questions case?

That's easy: data = fetchService.getAndUpdate(); takes about 30 seconds, and because you have only a single Thread for your scheduling, it must wait for the last iteration to finish, until it can start over again.

---

Solution

To fix that, simply replace the first wildcard with a 0:

0 */5 * * * *

And your job will run every 5 minutes.