Spring BootのScheduledTaskの検証

@EnableSchedulingを用いて
Spring BootのScheduling Tasksについて調査しました。

Spring BootにはSpring Batchという仕組みがあるのですが、やや大仰で使いにくいです。
Web系システムでの利用だと単純なスケジューリングのTaskで十分なことが多いと思います。
そんなわけで@EnableSchedulingのcronの機能について調査しました。

1. 5秒以内で終わるTask
2. 5秒以上かかるTask(10秒かかる)
3. 5秒以上かかるTask(10秒かかる)でFuture利用

ソースコード

全部入りはここに置いてます。 本当はコメント化で対処したくなかったのですが、mainメソッドやCommandLineRunnerやApplicationRunnerがあると同時に動いてわけがわからなくなるので、コメント化で対処してしまっています。
引数でやればいいじゃんという話もありますが、面倒でした。

ひとまずmainのクラスです

@SpringBootApplication
public class ScheduledTaskApplication implements ApplicationRunner {

    private static final Logger logger = LoggerFactory.getLogger(ScheduledTaskApplication.class);
    
    public static void main(String[] args) {
        SpringApplication.run(ScheduledTaskApplication.class, args);
    }

    @Override
    public void run(ApplicationArguments args) throws Exception {
        logger.info("{} invoked.", ReflectionUtil.getClassAndMethodName());
    }

}

今回のケースでは別にApplicationRunnerは不要でmainだけでよいのですが、ログを書きたかったので、 わざわざimplementsしているのはそのためです。 Javaラーにありがちですが、importは省略しています。

5秒以内で終わるTaskのケース

ScheduledTask.java

@EnableScheduling
@Component
public class ScheduledTask {
    /**
    * 5秒ごとに実行されるTask
    * Springから自動的に呼び出される
    * ちなみにメソッドの名前は何でもよい
    */
    @Scheduled(cron = "*/5 * * * * *")
    public void run() {
        logger.info("{} invoked.", ReflectionUtil.getClassAndMethodName());
        lightTask();
    }

    /**
    * 軽いTask
    */
    public void lightTask() {
        logger.info("{} start.", ReflectionUtil.getClassAndMethodName());
        logger.info("light task processing ...");
        // TODO something...
        logger.info("{} end.", ReflectionUtil.getClassAndMethodName());
    }
}

これで動かしてみます
実行すると当たり前ですが…

2019-02-10 04:47:08.745[main][INFO ][c.e.s.ScheduledTaskApplication          ] :ScheduledTaskApplication#run invoked.
2019-02-10 04:47:10.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 04:47:10.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#lightTask start.
2019-02-10 04:47:10.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :light task processing ...
2019-02-10 04:47:10.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#lightTask end.
2019-02-10 04:47:15.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 04:47:15.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#lightTask start.
2019-02-10 04:47:15.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :light task processing ...
2019-02-10 04:47:15.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#lightTask end.

こんな感じになります。

5秒以上かかるTask(10秒かかる場合)のケース

ScheduledTask.java

@EnableScheduling
@Component
public class ScheduledTask {
    /**
    * 5秒ごとに実行されるTask
    * Springから自動的に呼び出される
    * ちなみにメソッドの名前は何でもよい
    */
    @Scheduled(cron = "*/5 * * * * *")
    public void run() {
        logger.info("{} invoked.", ReflectionUtil.getClassAndMethodName());
        heavyTask();
    }

    /**
    * 重いTask
    */
    public void heavyTask() {
        logger.info("{} start.", ReflectionUtil.getClassAndMethodName());
        try {
            logger.info("heavy task processing ...");
            TimeUnit.SECONDS.sleep(10);
            // TODO something...
        } catch (InterruptedException e) {
            logger.error(e.getMessage(), e);
        }
        logger.info("{} end.", ReflectionUtil.getClassAndMethodName());
    }
}

2019-02-10 04:50:26.033[main][INFO ][c.e.s.ScheduledTaskApplication          ] :ScheduledTaskApplication#run invoked.
2019-02-10 04:50:30.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 04:50:30.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTask start.
2019-02-10 04:50:30.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :heavy task processing ...
2019-02-10 04:50:40.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTask end.
2019-02-10 04:50:45.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 04:50:45.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTask start.
2019-02-10 04:50:45.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :heavy task processing ...
2019-02-10 04:50:55.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTask end.
2019-02-10 04:51:00.006[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 04:51:00.006[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTask start.
2019-02-10 04:51:00.006[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :heavy task processing ...
2019-02-10 04:51:10.007[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTask end.

となり、ログをよく見ると、実行を待ち合わせてくれます。 本処理が10秒かかる場合、次回の起動は終わるまで待ってくれます。

5秒以上かかるTask(10秒かかる場合)でFuture利用のケース

ということで、別スレッドで本処理を起動してみました。
まぁ、別スレッドということなんで、処理は当然、待ち合わせなくなるので、
Springが決まった時間に起動をかける当たり前の挙動になります。
とはいえ、スレッドの多重起動が起きないように終わるまで次回の処理を起動しないように制御はしています。
こちらのメリットはプログラム自体が異常停止しているかそうでないか、
ログを見ると一目瞭然ということでしょうか
ちなみにFutureTaskは別クラスにする必要は特にないんですが、GitHubにあげるソースコードで見にくくなるので、
とりあえず分けてます。
ScheduledTask.java

@EnableScheduling
@Component
public class ScheduledTask {

    private static final Logger logger = LoggerFactory.getLogger(ScheduledTask.class);
    private ExecutorService executorService = Executors.newSingleThreadExecutor();
    private Future<?> future = null;
    @Autowired
    FutureTask futureTask;

    /**
    * 重いTask (Future利用)
    */
    public void heavyTaskWithFuture() {
        logger.info("{} start.", ReflectionUtil.getClassAndMethodName());
        if (future == null || future.isDone()) {
            future = executorService.submit(futureTask);  // 別スレッドで実行
        }
        logger.info("{} end.", ReflectionUtil.getClassAndMethodName());
    }
}

別スレッドで呼び出されるTask FutureTask.java

@Component
public class FutureTask implements Callable<Boolean> {
    private static final Logger logger = LoggerFactory.getLogger(ScheduledTask.class);

    @Override
    public Boolean call() throws Exception {
        logger.info("{} start.", ReflectionUtil.getClassAndMethodName());
        try {
            logger.info("future heavy task processing ...");
            TimeUnit.SECONDS.sleep(10);
            // TODO something...
        } catch (InterruptedException e) {
            logger.error(e.getMessage(), e);
            return false;
        }
        logger.info("{} end.", ReflectionUtil.getClassAndMethodName());
        return true;
    }
}

これを実行すると…、

2019-02-10 05:00:24.189[main][INFO ][c.e.s.ScheduledTaskApplication          ] :ScheduledTaskApplication#run invoked.
2019-02-10 05:00:25.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 05:00:25.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture start.
2019-02-10 05:00:25.003[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture end.
2019-02-10 05:00:25.003[pool-1-thread-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :FutureTask#call start.
2019-02-10 05:00:25.003[pool-1-thread-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :future heavy task processing ...
2019-02-10 05:00:30.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 05:00:30.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture start.
2019-02-10 05:00:30.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture end.
2019-02-10 05:00:35.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 05:00:35.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture start.
2019-02-10 05:00:35.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture end.
2019-02-10 05:00:35.003[pool-1-thread-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :FutureTask#call end.
2019-02-10 05:00:40.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 05:00:40.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture start.
2019-02-10 05:00:40.001[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture end.
2019-02-10 05:00:40.002[pool-1-thread-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :FutureTask#call start.
2019-02-10 05:00:40.002[pool-1-thread-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :future heavy task processing ...
2019-02-10 05:00:45.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#run invoked.
2019-02-10 05:00:45.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture start.
2019-02-10 05:00:45.002[scheduling-1][INFO ][c.e.scheduledtask.tasks.ScheduledTask   ] :ScheduledTask#heavyTaskWithFuture end.

ちょっとわかりにくいですが、必ず5分に1回呼び出されています。

とりあえず、自分でお手軽バッチを作るなら3のパターンかなと思った次第です。
にしても、Javaのマルチスレッドプログラミングはマジで便利…。 C++だとめんどくさすぎる。
ちなみにRx系は複雑度が高すぎな気がしていまいち好きになれない…。

補足

Spring Bootですが1プロジェクトに別にいくつもエントリーポイントがあってもよい。 コマンドラインからの起動の時は同時に動きます。

番外編

そもそも例えば10秒に1回スケジュールしたいときに、
cron = "*/10 * * * * *"と"0/10 * * * * *"と書いたときに一緒な気がするけど、
本当に一緒か？と思い調べてみました。
公式は前者で一応書いているような気がする…
CronSequenceGenerator (Spring Framework 5.2.7.RELEASE API)　　 ということで…

検証コード

cronの文字列をパースしているのはCronSequenceGeneratorで、 next()を呼び出すと次の時刻を返してくれるっぽい。

import java.time.LocalDateTime;
import java.time.ZoneId;
import java.time.ZonedDateTime;
import java.time.format.DateTimeFormatter;
import java.util.Date;

import org.springframework.scheduling.support.CronSequenceGenerator;

public class App {
    public static void main(String[] args) {
        System.out.println("\"*/10 * * * * *\"と\n"
                + "\"0/10 * * * * *\"は同じなのかテスト");
        {
            Date date1 = stringToDate("2019-08-14 10:00:00");
            System.out.println(date1);
            Date d1 = test1(date1);
            System.out.println(d1);
            Date d2 = test2(date1);
            System.out.println(d2);
            System.out.println(d1.equals(d2));
        }
        System.out.println("-------------------");
        {
            Date date1 = stringToDate("2019-08-14 10:00:05");
            System.out.println(date1);
            Date d1 = test1(date1);
            System.out.println(d1);
            Date d2 = test2(date1);
            System.out.println(d2);
            System.out.println(d1.equals(d2));
        }
        System.out.println("-------------------");
        {
            Date date1 = stringToDate("2019-08-14 10:00:09");
            System.out.println(date1);
            Date d1 = test1(date1);
            System.out.println(d1);
            Date d2 = test2(date1);
            System.out.println(d2);
            System.out.println(d1.equals(d2));
        }
        System.out.println("-------------------");
        {
            Date date1 = stringToDate("2019-08-14 10:00:10");
            System.out.println(date1);
            Date d1 = test1(date1);
            System.out.println(d1);
            Date d2 = test2(date1);
            System.out.println(d2);
            System.out.println(d1.equals(d2));
        }
        System.out.println("-------------------");
        {
            Date date1 = stringToDate("2019-08-14 10:00:11");
            System.out.println(date1);
            Date d1 = test1(date1);
            System.out.println(d1);
            Date d2 = test2(date1);
            System.out.println(d2);
            System.out.println(d1.equals(d2));
        }
        System.out.println("-------------------");
        {
            Date date1 = stringToDate("2019-08-14 10:00:41");
            System.out.println(date1);
            Date d1 = test1(date1);
            System.out.println(d1);
            Date d2 = test2(date1);
            System.out.println(d2);
            System.out.println(d1.equals(d2));
        }
        System.out.println("両者は同じなので\"*/10 * * * * *\"を使ったほうがよさそう");
    }
    
    private static Date test1(Date date) {
        final String CronSched = "*/10 * * * * *";
        CronSequenceGenerator csg = new CronSequenceGenerator(CronSched);
        return csg.next(date);
    }
    
    private static Date test2(Date date) {
        final String CronSched = "0/10 * * * * *";
        CronSequenceGenerator csg = new CronSequenceGenerator(CronSched);
        return csg.next(date);
    }
    
    private static Date stringToDate(final String dateStr) {
        LocalDateTime ldt = LocalDateTime.parse(dateStr, DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss"));
        return Date.from(ZonedDateTime.of(ldt, ZoneId.systemDefault()).toInstant());
    }
}

結果一緒でした。前者で書くほうが良さそう。ちなみに普通のcrontabはどうなのかは知りません…。

参考リンク

Spring & Spring Boot

Getting Started | Scheduling Tasks
Integration

ApplicationRunnerとCommandLineRunnerについて

Spring Boot: ApplicationRunner and CommandLineRunner - DZone Java
Spring Bootでコマンドラインアプリを作る時の注意点 - Qiita

Future関連

言語によってちょっと違うFuture/Promiseをまとめてみた(1) - Qiita