Walk, Don't Run

若手エンジニアが日々学んだことをさらけ出すブログです

springで@Asyncによる非同期処理でスレッドプールする場合の設定周り

以下の辺りが設定可能なので、それぞれメモを残す。

  • スレッドプールの方式（Executor）
  • スレッドプールのパラメーター（ThreadPoolTaskExecutor の設定）
  • Reject時（スレッド数が溢れた場合）のポリシー

スレッドプール方式（Executor）

@Asyncのついたメソッドを呼び出す場合、org.springframework.core.task.TaskExecutor をbean登録することで任意のExecutorに処理をさせることができる。TaskExecutorはスレッドプールをどのように行うかを定義するもので、java.util.concurrent.Executor を継承したinterface。以下のExecutorが用意されており、デフォルトだとSimpleAsyncTaskExecutorが使われるが、スレッドプールをしたい場合は通常はThreadPoolTaskExecutorを使えば良さそう。

  • SyncTaskExecutor
    • 非同期で実行されない。テストとか用。
  • SimpleAsyncTaskExecutor
    • 呼び出すたびに新しいスレッドを生成する。デフォルトだとこれ。
  • ConcurrentTaskExecutor
    • java.util.concurrent.Executor のadaptorとして実装。ThreadPoolTaskExecutorで要件が満たせない場合に代わりに使えるらしい。
  • ThreadPoolTaskExecutor
    • 基本はこれでOK。Bean形式でjava.util.concurrent.ThreadPoolExecutorの設定が可能。

スレッドプールのパラメーター（ThreadPoolTaskExecutor の設定）

ThreadPoolTaskExecutorはjava.util.concurrent.ThreadPoolExecutorをラップしており、主にcorePoolSize, maxPoolSize, queueCapacity の3つのパラメーターでスレッドプールの挙動を設定する。

それぞれのパラメーターの挙動については、 https://blog.ik.am/entries/443 が非常に理解しやすいので、まずはここを読むのがおすすめ。

デフォルトだとcorePoolSizeが1, maxPoolSizeとqueueCapacityがInteger.MAX_VALUEになっているので、このままだと実質シングルスレッドの処理となる。

スレッド数がmaxPoolSizeを超えるとTaskRejectedExceptionが発生するので、必要なら適切なハンドリングを行う（後述）。

その他に、keepAliveSecondがある。アイドル状態のスレッドがこの時間を過ぎると削除されるらしい（corePoolSizeを越えてプール内にスレッドが存在する場合）。デフォルトは60秒のようだ。

Reject時（スレッド数が溢れた場合）のポリシー

タスクの消化が追いつかない場合どんどんスレッドが膨らみ、やがてmaxPoolSizeを超えると例外が投げられてしまう。個人的には、maxを越えたらその時点で例外を投げるのではなく、スレッドが消化されるまで待機されるような動きになっていてほしい。

・・・とか思っていたら、同じような疑問がstackoverflowにあった。

https://stackoverflow.com/questions/49290054/taskrejectedexception-in-threadpooltaskexecutor

例外を投げるのを防ぐには、一番上の回答を見るに、以下のような方法で対応できそう。

  1. キューサイズを指定せず、無限にキューにタスクを積む作りにする。スレッド数の上限はcorePoolSizeで、タスクが終わる度にキューから新しいタスクが取り出される。
  2. RejectedExecutionHandlerを指定する
  3. 独自のExecutorを実装する（Semaphoreとか利用して）

1が楽そうだが、これだとスレッド数がcorePoolSizeに固定されてしまい、スケーラビリティが損なわれるように見える。3はなんだか面倒そう。ということで2を調べてみる。

RejectedExecutionHandlerは自分で実装しても良いが、あらかじめ用意されているクラスがある。

  • CallerRunsPolicy
  • AbortPolicy （デフォルトだとこれ）
  • DiscardPolicy
  • DiscardOldestPolicy

CallerRunsPolicyは、呼び出し元がそのままタスクを実行するというもの。

参考: https://stackoverflow.com/questions/46064786/rejectedexecutionhandler-callerrunspolicy-vs-abortpolicy

とりあえず自分のユースケースだとこの動きで問題なさそう。

実装例

以下のような設定をした場合の挙動を追いかけてみる。コードの全体は、 https://github.com/suzukimit/spring-demo/tree/master/spring-async-demo へ。

メインタスク（@Scheduledで毎秒呼び出される）

@Component
class MainTask(val subTask: SubTask) {

    @Scheduled(fixedRateString = "1000")
    fun execute() {
        taskCount++
        println("${Date()} : task$taskCount start : ${Thread.currentThread().id} ")
        for (i in 1..5) {
            subTask.execute(taskCount, i)
        }
        println("${Date()} : task$taskCount end   : ${Thread.currentThread().id} ")
    }

    companion object {
        var taskCount = 0
    }
}

サブタスク（@Asyncでメインタスクから5回呼び出される）

@Component
class SubTask {
    @Async
    fun execute(taskCount: Int, subTaskCount: Int) {
        println("${Date()} : sub-task$taskCount-$subTaskCount start : ${Thread.currentThread().id}")
        Thread.sleep(3000)
        println("${Date()} : sub-task$taskCount-$subTaskCount end   : ${Thread.currentThread().id}")
    }
}

TaskExecutorの設定クラス

@Configuration
class TaskExecutorConfig {
    @Bean
    fun taskExecutor(): TaskExecutor {
        return ThreadPoolTaskExecutor().apply {
            corePoolSize = 2
            maxPoolSize = 4
            setQueueCapacity(4)
            setRejectedExecutionHandler(ThreadPoolExecutor.CallerRunsPolicy())
        }
    }
}

※動作確認のために適当な小さめのPoolSizeを指定。実運用ではより大きなサイズにチューニングしていく必要があるかと。

コンソールの出力内容

適当に、1分間くらい流した結果を貼り付ける。

Mon Nov 04 15:59:44 JST 2019 : task1 start : 21 
Mon Nov 04 15:59:44 JST 2019 : task1 end   : 21 
Mon Nov 04 15:59:44 JST 2019 : sub-task1-1 start : 24
Mon Nov 04 15:59:44 JST 2019 : sub-task1-2 start : 25
Mon Nov 04 15:59:45 JST 2019 : task2 start : 21 
Mon Nov 04 15:59:45 JST 2019 : sub-task2-2 start : 31
Mon Nov 04 15:59:45 JST 2019 : sub-task2-4 start : 21
Mon Nov 04 15:59:45 JST 2019 : sub-task2-3 start : 32
Mon Nov 04 15:59:47 JST 2019 : sub-task1-1 end   : 24
Mon Nov 04 15:59:47 JST 2019 : sub-task1-2 end   : 25
Mon Nov 04 15:59:47 JST 2019 : sub-task1-3 start : 24
Mon Nov 04 15:59:47 JST 2019 : sub-task1-4 start : 25
Mon Nov 04 15:59:48 JST 2019 : sub-task2-2 end   : 31
Mon Nov 04 15:59:48 JST 2019 : sub-task2-3 end   : 32
Mon Nov 04 15:59:48 JST 2019 : sub-task2-4 end   : 21
Mon Nov 04 15:59:48 JST 2019 : sub-task2-1 start : 32
Mon Nov 04 15:59:48 JST 2019 : sub-task1-5 start : 31
Mon Nov 04 15:59:48 JST 2019 : task2 end   : 21 
Mon Nov 04 15:59:48 JST 2019 : task3 start : 21 
Mon Nov 04 15:59:48 JST 2019 : sub-task3-4 start : 21
Mon Nov 04 15:59:50 JST 2019 : sub-task1-4 end   : 25
Mon Nov 04 15:59:50 JST 2019 : sub-task1-3 end   : 24
Mon Nov 04 15:59:50 JST 2019 : sub-task2-5 start : 25
Mon Nov 04 15:59:50 JST 2019 : sub-task3-1 start : 24
Mon Nov 04 15:59:51 JST 2019 : sub-task1-5 end   : 31
Mon Nov 04 15:59:51 JST 2019 : sub-task2-1 end   : 32
Mon Nov 04 15:59:51 JST 2019 : sub-task3-4 end   : 21
Mon Nov 04 15:59:51 JST 2019 : sub-task3-3 start : 32
Mon Nov 04 15:59:51 JST 2019 : sub-task3-2 start : 31
Mon Nov 04 15:59:51 JST 2019 : task3 end   : 21 
Mon Nov 04 15:59:51 JST 2019 : task4 start : 21 
Mon Nov 04 15:59:51 JST 2019 : sub-task4-4 start : 21
Mon Nov 04 15:59:53 JST 2019 : sub-task2-5 end   : 25
Mon Nov 04 15:59:53 JST 2019 : sub-task3-1 end   : 24
Mon Nov 04 15:59:53 JST 2019 : sub-task3-5 start : 25
Mon Nov 04 15:59:53 JST 2019 : sub-task4-1 start : 24
Mon Nov 04 15:59:54 JST 2019 : sub-task3-2 end   : 31
Mon Nov 04 15:59:54 JST 2019 : sub-task4-4 end   : 21
Mon Nov 04 15:59:54 JST 2019 : sub-task4-2 start : 31
Mon Nov 04 15:59:54 JST 2019 : sub-task3-3 end   : 32
Mon Nov 04 15:59:54 JST 2019 : task4 end   : 21 
Mon Nov 04 15:59:54 JST 2019 : sub-task4-3 start : 32
Mon Nov 04 15:59:54 JST 2019 : task5 start : 21 
Mon Nov 04 15:59:54 JST 2019 : sub-task5-4 start : 21
Mon Nov 04 15:59:56 JST 2019 : sub-task4-1 end   : 24
Mon Nov 04 15:59:56 JST 2019 : sub-task3-5 end   : 25
Mon Nov 04 15:59:56 JST 2019 : sub-task4-5 start : 24
Mon Nov 04 15:59:56 JST 2019 : sub-task5-1 start : 25
Mon Nov 04 15:59:57 JST 2019 : sub-task4-2 end   : 31
Mon Nov 04 15:59:57 JST 2019 : sub-task5-2 start : 31
Mon Nov 04 15:59:57 JST 2019 : sub-task4-3 end   : 32
Mon Nov 04 15:59:57 JST 2019 : sub-task5-4 end   : 21
Mon Nov 04 15:59:57 JST 2019 : sub-task5-3 start : 32
Mon Nov 04 15:59:57 JST 2019 : task5 end   : 21 
Mon Nov 04 15:59:57 JST 2019 : task6 start : 21 
Mon Nov 04 15:59:57 JST 2019 : sub-task6-4 start : 21
Mon Nov 04 15:59:59 JST 2019 : sub-task5-1 end   : 25
Mon Nov 04 15:59:59 JST 2019 : sub-task4-5 end   : 24
Mon Nov 04 15:59:59 JST 2019 : sub-task5-5 start : 25
Mon Nov 04 15:59:59 JST 2019 : sub-task6-1 start : 24
Mon Nov 04 16:00:00 JST 2019 : sub-task5-2 end   : 31
Mon Nov 04 16:00:00 JST 2019 : sub-task5-3 end   : 32
Mon Nov 04 16:00:00 JST 2019 : sub-task6-2 start : 31
Mon Nov 04 16:00:00 JST 2019 : sub-task6-3 start : 32
Mon Nov 04 16:00:00 JST 2019 : sub-task6-4 end   : 21
Mon Nov 04 16:00:00 JST 2019 : task6 end   : 21 
Mon Nov 04 16:00:00 JST 2019 : task7 start : 21 
Mon Nov 04 16:00:00 JST 2019 : sub-task7-4 start : 21
Mon Nov 04 16:00:02 JST 2019 : sub-task6-1 end   : 24
Mon Nov 04 16:00:02 JST 2019 : sub-task5-5 end   : 25
Mon Nov 04 16:00:02 JST 2019 : sub-task6-5 start : 24
Mon Nov 04 16:00:02 JST 2019 : sub-task7-1 start : 25
Mon Nov 04 16:00:03 JST 2019 : sub-task6-2 end   : 31
Mon Nov 04 16:00:03 JST 2019 : sub-task6-3 end   : 32
Mon Nov 04 16:00:03 JST 2019 : sub-task7-2 start : 31
Mon Nov 04 16:00:03 JST 2019 : sub-task7-4 end   : 21
Mon Nov 04 16:00:03 JST 2019 : sub-task7-3 start : 32
Mon Nov 04 16:00:03 JST 2019 : task7 end   : 21 
Mon Nov 04 16:00:03 JST 2019 : task8 start : 21 
Mon Nov 04 16:00:03 JST 2019 : sub-task8-4 start : 21
Mon Nov 04 16:00:05 JST 2019 : sub-task7-1 end   : 25
Mon Nov 04 16:00:05 JST 2019 : sub-task6-5 end   : 24
Mon Nov 04 16:00:05 JST 2019 : sub-task7-5 start : 25
Mon Nov 04 16:00:05 JST 2019 : sub-task8-1 start : 24
Mon Nov 04 16:00:06 JST 2019 : sub-task7-2 end   : 31
Mon Nov 04 16:00:06 JST 2019 : sub-task8-4 end   : 21
Mon Nov 04 16:00:06 JST 2019 : sub-task7-3 end   : 32
Mon Nov 04 16:00:06 JST 2019 : sub-task8-2 start : 31
Mon Nov 04 16:00:06 JST 2019 : task8 end   : 21 
Mon Nov 04 16:00:06 JST 2019 : sub-task8-3 start : 32
Mon Nov 04 16:00:06 JST 2019 : task9 start : 21 
Mon Nov 04 16:00:06 JST 2019 : sub-task9-4 start : 21
Mon Nov 04 16:00:08 JST 2019 : sub-task8-1 end   : 24
Mon Nov 04 16:00:08 JST 2019 : sub-task7-5 end   : 25
Mon Nov 04 16:00:08 JST 2019 : sub-task9-1 start : 25
Mon Nov 04 16:00:08 JST 2019 : sub-task8-5 start : 24
Mon Nov 04 16:00:09 JST 2019 : sub-task8-3 end   : 32
Mon Nov 04 16:00:09 JST 2019 : sub-task9-4 end   : 21
Mon Nov 04 16:00:09 JST 2019 : sub-task8-2 end   : 31
Mon Nov 04 16:00:09 JST 2019 : sub-task9-2 start : 32
Mon Nov 04 16:00:09 JST 2019 : task9 end   : 21 
Mon Nov 04 16:00:09 JST 2019 : sub-task9-3 start : 31
Mon Nov 04 16:00:09 JST 2019 : task10 start : 21 
Mon Nov 04 16:00:09 JST 2019 : sub-task10-4 start : 21
Mon Nov 04 16:00:11 JST 2019 : sub-task8-5 end   : 24
Mon Nov 04 16:00:11 JST 2019 : sub-task9-1 end   : 25
Mon Nov 04 16:00:11 JST 2019 : sub-task10-1 start : 25
Mon Nov 04 16:00:11 JST 2019 : sub-task9-5 start : 24
Mon Nov 04 16:00:12 JST 2019 : sub-task10-4 end   : 21
Mon Nov 04 16:00:12 JST 2019 : sub-task9-2 end   : 32
Mon Nov 04 16:00:12 JST 2019 : task10 end   : 21 
Mon Nov 04 16:00:12 JST 2019 : task11 start : 21 
Mon Nov 04 16:00:12 JST 2019 : sub-task11-3 start : 21
Mon Nov 04 16:00:12 JST 2019 : sub-task9-3 end   : 31
Mon Nov 04 16:00:12 JST 2019 : sub-task10-3 start : 31
Mon Nov 04 16:00:12 JST 2019 : sub-task10-2 start : 32
Mon Nov 04 16:00:14 JST 2019 : sub-task10-1 end   : 25
Mon Nov 04 16:00:14 JST 2019 : sub-task9-5 end   : 24
Mon Nov 04 16:00:14 JST 2019 : sub-task10-5 start : 25
Mon Nov 04 16:00:14 JST 2019 : sub-task11-1 start : 24
Mon Nov 04 16:00:15 JST 2019 : sub-task11-3 end   : 21
Mon Nov 04 16:00:15 JST 2019 : sub-task10-3 end   : 31
Mon Nov 04 16:00:15 JST 2019 : sub-task10-2 end   : 32
Mon Nov 04 16:00:15 JST 2019 : task11 end   : 21 
Mon Nov 04 16:00:15 JST 2019 : sub-task11-2 start : 31
Mon Nov 04 16:00:15 JST 2019 : sub-task11-4 start : 32
Mon Nov 04 16:00:15 JST 2019 : task12 start : 21 
Mon Nov 04 16:00:15 JST 2019 : sub-task12-4 start : 21
Mon Nov 04 16:00:17 JST 2019 : sub-task10-5 end   : 25
Mon Nov 04 16:00:17 JST 2019 : sub-task11-1 end   : 24
Mon Nov 04 16:00:17 JST 2019 : sub-task11-5 start : 25
Mon Nov 04 16:00:17 JST 2019 : sub-task12-1 start : 24
Mon Nov 04 16:00:18 JST 2019 : sub-task11-4 end   : 32
Mon Nov 04 16:00:18 JST 2019 : sub-task12-4 end   : 21
Mon Nov 04 16:00:18 JST 2019 : sub-task11-2 end   : 31
Mon Nov 04 16:00:18 JST 2019 : sub-task12-2 start : 32
Mon Nov 04 16:00:18 JST 2019 : sub-task12-3 start : 31
Mon Nov 04 16:00:18 JST 2019 : task12 end   : 21 
Mon Nov 04 16:00:18 JST 2019 : task13 start : 21 
Mon Nov 04 16:00:18 JST 2019 : sub-task13-4 start : 21
Mon Nov 04 16:00:20 JST 2019 : sub-task11-5 end   : 25
Mon Nov 04 16:00:20 JST 2019 : sub-task12-1 end   : 24
Mon Nov 04 16:00:20 JST 2019 : sub-task12-5 start : 25
Mon Nov 04 16:00:20 JST 2019 : sub-task13-1 start : 24
Mon Nov 04 16:00:21 JST 2019 : sub-task12-3 end   : 31
Mon Nov 04 16:00:21 JST 2019 : sub-task12-2 end   : 32
Mon Nov 04 16:00:21 JST 2019 : sub-task13-4 end   : 21
Mon Nov 04 16:00:21 JST 2019 : sub-task13-2 start : 31
Mon Nov 04 16:00:21 JST 2019 : sub-task13-3 start : 32
Mon Nov 04 16:00:21 JST 2019 : task13 end   : 21 
Mon Nov 04 16:00:21 JST 2019 : task14 start : 21 
Mon Nov 04 16:00:21 JST 2019 : sub-task14-4 start : 21
Mon Nov 04 16:00:23 JST 2019 : sub-task13-1 end   : 24
Mon Nov 04 16:00:23 JST 2019 : sub-task12-5 end   : 25
Mon Nov 04 16:00:23 JST 2019 : sub-task13-5 start : 24
Mon Nov 04 16:00:23 JST 2019 : sub-task14-1 start : 25
Mon Nov 04 16:00:24 JST 2019 : sub-task13-3 end   : 32
Mon Nov 04 16:00:24 JST 2019 : sub-task14-4 end   : 21
Mon Nov 04 16:00:24 JST 2019 : sub-task13-2 end   : 31
Mon Nov 04 16:00:24 JST 2019 : sub-task14-2 start : 32
Mon Nov 04 16:00:24 JST 2019 : task14 end   : 21 
Mon Nov 04 16:00:24 JST 2019 : sub-task14-3 start : 31
Mon Nov 04 16:00:24 JST 2019 : task15 start : 21 
Mon Nov 04 16:00:24 JST 2019 : sub-task15-4 start : 21
Mon Nov 04 16:00:26 JST 2019 : sub-task14-1 end   : 25
Mon Nov 04 16:00:26 JST 2019 : sub-task13-5 end   : 24
Mon Nov 04 16:00:26 JST 2019 : sub-task15-1 start : 24
Mon Nov 04 16:00:26 JST 2019 : sub-task14-5 start : 25
Mon Nov 04 16:00:27 JST 2019 : sub-task14-2 end   : 32
Mon Nov 04 16:00:27 JST 2019 : sub-task15-2 start : 32
Mon Nov 04 16:00:27 JST 2019 : sub-task14-3 end   : 31
Mon Nov 04 16:00:27 JST 2019 : sub-task15-4 end   : 21
Mon Nov 04 16:00:27 JST 2019 : sub-task15-3 start : 31
Mon Nov 04 16:00:27 JST 2019 : task15 end   : 21 
Mon Nov 04 16:00:27 JST 2019 : task16 start : 21 
Mon Nov 04 16:00:27 JST 2019 : sub-task16-4 start : 21
Mon Nov 04 16:00:29 JST 2019 : sub-task14-5 end   : 25
Mon Nov 04 16:00:29 JST 2019 : sub-task15-1 end   : 24
Mon Nov 04 16:00:29 JST 2019 : sub-task15-5 start : 25
Mon Nov 04 16:00:29 JST 2019 : sub-task16-1 start : 24
Mon Nov 04 16:00:30 JST 2019 : sub-task15-2 end   : 32
Mon Nov 04 16:00:30 JST 2019 : sub-task16-2 start : 32
Mon Nov 04 16:00:30 JST 2019 : sub-task16-4 end   : 21
Mon Nov 04 16:00:30 JST 2019 : sub-task15-3 end   : 31
Mon Nov 04 16:00:30 JST 2019 : task16 end   : 21 
Mon Nov 04 16:00:30 JST 2019 : sub-task16-3 start : 31
Mon Nov 04 16:00:30 JST 2019 : task17 start : 21 
Mon Nov 04 16:00:30 JST 2019 : sub-task17-4 start : 21
Mon Nov 04 16:00:32 JST 2019 : sub-task16-1 end   : 24
Mon Nov 04 16:00:32 JST 2019 : sub-task15-5 end   : 25
Mon Nov 04 16:00:32 JST 2019 : sub-task16-5 start : 24
Mon Nov 04 16:00:32 JST 2019 : sub-task17-1 start : 25
Mon Nov 04 16:00:33 JST 2019 : sub-task16-2 end   : 32
Mon Nov 04 16:00:33 JST 2019 : sub-task17-2 start : 32
Mon Nov 04 16:00:33 JST 2019 : sub-task17-4 end   : 21
Mon Nov 04 16:00:33 JST 2019 : sub-task16-3 end   : 31
Mon Nov 04 16:00:33 JST 2019 : task17 end   : 21 
Mon Nov 04 16:00:33 JST 2019 : sub-task17-3 start : 31
Mon Nov 04 16:00:33 JST 2019 : task18 start : 21 
Mon Nov 04 16:00:33 JST 2019 : sub-task18-4 start : 21
Mon Nov 04 16:00:35 JST 2019 : sub-task16-5 end   : 24
Mon Nov 04 16:00:35 JST 2019 : sub-task17-1 end   : 25
Mon Nov 04 16:00:35 JST 2019 : sub-task18-1 start : 25
Mon Nov 04 16:00:35 JST 2019 : sub-task17-5 start : 24
Mon Nov 04 16:00:36 JST 2019 : sub-task17-2 end   : 32
Mon Nov 04 16:00:36 JST 2019 : sub-task18-2 start : 32
Mon Nov 04 16:00:36 JST 2019 : sub-task17-3 end   : 31
Mon Nov 04 16:00:36 JST 2019 : sub-task18-3 start : 31
Mon Nov 04 16:00:36 JST 2019 : sub-task18-4 end   : 21
Mon Nov 04 16:00:36 JST 2019 : task18 end   : 21 
Mon Nov 04 16:00:36 JST 2019 : task19 start : 21 
Mon Nov 04 16:00:36 JST 2019 : sub-task19-4 start : 21
Mon Nov 04 16:00:38 JST 2019 : sub-task17-5 end   : 24
Mon Nov 04 16:00:38 JST 2019 : sub-task18-1 end   : 25
Mon Nov 04 16:00:38 JST 2019 : sub-task18-5 start : 24
Mon Nov 04 16:00:38 JST 2019 : sub-task19-1 start : 25
Mon Nov 04 16:00:39 JST 2019 : sub-task18-2 end   : 32
Mon Nov 04 16:00:39 JST 2019 : sub-task18-3 end   : 31
Mon Nov 04 16:00:39 JST 2019 : sub-task19-3 start : 31
Mon Nov 04 16:00:39 JST 2019 : sub-task19-2 start : 32
Mon Nov 04 16:00:39 JST 2019 : sub-task19-4 end   : 21
Mon Nov 04 16:00:39 JST 2019 : task19 end   : 21 
Mon Nov 04 16:00:39 JST 2019 : task20 start : 21 
Mon Nov 04 16:00:39 JST 2019 : sub-task20-4 start : 21
Mon Nov 04 16:00:41 JST 2019 : sub-task19-1 end   : 25
Mon Nov 04 16:00:41 JST 2019 : sub-task19-5 start : 25
Mon Nov 04 16:00:41 JST 2019 : sub-task18-5 end   : 24
Mon Nov 04 16:00:41 JST 2019 : sub-task20-1 start : 24
Mon Nov 04 16:00:42 JST 2019 : sub-task20-4 end   : 21
Mon Nov 04 16:00:42 JST 2019 : sub-task19-3 end   : 31
Mon Nov 04 16:00:42 JST 2019 : sub-task19-2 end   : 32
Mon Nov 04 16:00:42 JST 2019 : task20 end   : 21 
Mon Nov 04 16:00:42 JST 2019 : sub-task20-3 start : 32
Mon Nov 04 16:00:42 JST 2019 : sub-task20-2 start : 31
Mon Nov 04 16:00:42 JST 2019 : task21 start : 21 
Mon Nov 04 16:00:42 JST 2019 : sub-task21-4 start : 21
Mon Nov 04 16:00:44 JST 2019 : sub-task19-5 end   : 25
Mon Nov 04 16:00:44 JST 2019 : sub-task20-1 end   : 24
Mon Nov 04 16:00:44 JST 2019 : sub-task20-5 start : 24

コンソールの出力を見ると以下のことが確認できる。

  • スレッドIDを列挙すると、21, 24, 25, 31, 32の5つが登場。このうち21が呼び出し元のスレッドで、それ以外の4つが@Asyncで実行されたスレッド。
  • @Asyncで実行されたスレッドは全部で4つあり、maxPoolSizeに一致する。
  • 約1分間の間に20個のタスクが完了。
  • 約1分間の間に97個のサブタスクが完了。

毎秒5個のサブタスクを実行しているが、実際には1.6個/秒くらいのタスクしかこなせていない。これは結局のところmaxPoolSizeを超えてメインタスク（スレッド21）がCallerRunsPolicyによって毎回サブタスクを実行する羽目になり、そこで3秒間のスリープが入り、3秒に1個くらいのタスクしか実行できないため。結果として、5個/3秒くらいしかサブタスクがこなせないということらしい。

試しにcorePoolSizeやmaxPoolSizeを十分大きい値（10とか）にしてみると、5個/秒くらいのパフォーマンスになることが確認できる。ということで、設定値（Reject時のポリシー含む）やタスクのsleep時間などを色々と変更しながら挙動を追いかけると理解が深まりそう。