Ktor Serverのリクエストハンドラーで同期処理を行うと何が起きるのか
Ktor Server はKotlinのコルーチンを活用したWebアプリケーションフレームワークです。 コルーチンによる非同期処理性能を発揮するためには同期処理をなるべく避けるべきですが、例えばJVM言語におけるデータベース接続で広く使われているJDBCでは、同期処理が前提になっています1。
実際のところ、Ktor Serverで同期処理を行なった場合に、どのような挙動になるかよく分かってなかったので、改めて調べてみました。
実験・調査した環境は次の通りです。
- AdoptOpenJDK 11
- Kotlin 1.5.21
- Ktor Server 1.6.2
- Netty 4.1.63
- JDBI 3.21.0
- HikariCP 5.0.0
- Logback Classic 1.2.3
- PostgreSQL 13
結論
結論を先に置いておきます。
Ktor Serverにおいて、リクエストを処理するスレッドはラウンドロビンで順番に割り当てられるので、時間のかかる同期処理があると、後続のリクエストが同期処理の完了を待たされてしまう。
実験用のアプリケーション
動作を確認するために、以下の2種類のエンドポイントをもつアプリケーションを用意しました。2つともPosgreSQLの pg_sleep() 関数で {seconds} 秒だけ待つという動作は同じで、処理を実行するコルーチンコンテキストだけが異なります。
- 同期エンドポイント（
/sleep-sync/{seconds}）- リクエストを処理するコルーチンコンテキストで同期処理を行う
- 非同期エンドポイント（
/sleep-async/{seconds}）- IO専用のコルーチンコンテキストで同期処理を行う（リクエストを処理するコルーチンコンテキストから見ると非同期）
具体的な実装の違いは以下のとおりです。ソースコード全体はGitHubのリポジトリに置いてあります。
// 同期エンドポイントのクエリ実行 fun sleepSync(seconds: Double): Double { val sql = "SELECT pg_sleep(:seconds)" return jdbi.withHandle<Double, Exception> { handle -> logger.info("sleepSync($seconds)") handle.createQuery(sql).bind("seconds", seconds).mapToMap().list() seconds } } // 非同期エンドポイントのクエリ実行 suspend fun sleepAsync(seconds: Double): Double { val sql = "SELECT pg_sleep(:seconds)" return withContext(Dispatchers.IO) { jdbi.withHandle<Double, Exception> { handle -> logger.info("sleepAsync($seconds)") handle.createQuery(sql).bind("seconds", seconds).mapToMap().list() seconds } } }
挙動の確認
同期エンドポイント
Apache Benchを使って、16リクエストを1並列で送ります。 ab コマンドでは -n で全体のリクエスト数を、 -c で並列実行数を指定します。
$ ab -n 16 -c 1 http://localhost:8080/sleep-sync/0.1
この時のサーバー側のログは次のようになります。各行で時刻の次の [eventLoopGroupProxy-4-X] がスレッド名です。 200 OK: GET - /sleep-sync/0.1 のようなリクエストログは、レスポンスを返す直前に出力されることに注意してください。
これをみると、リクエストを処理するためのスレッドが8個2あり、リクエストごとに順番に使用されていることがわかります。クエリも同じスレッドで実行されています。
19:50:57.808 [eventLoopGroupProxy-4-1] INFO SleepQueryService - sleepSync(0.1) 19:50:57.921 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:57.937 [eventLoopGroupProxy-4-2] INFO SleepQueryService - sleepSync(0.1) 19:50:58.046 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.066 [eventLoopGroupProxy-4-3] INFO SleepQueryService - sleepSync(0.1) 19:50:58.171 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.188 [eventLoopGroupProxy-4-4] INFO SleepQueryService - sleepSync(0.1) 19:50:58.299 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.319 [eventLoopGroupProxy-4-5] INFO SleepQueryService - sleepSync(0.1) 19:50:58.424 [eventLoopGroupProxy-4-5] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.429 [eventLoopGroupProxy-4-6] INFO SleepQueryService - sleepSync(0.1) 19:50:58.535 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.541 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 19:50:58.652 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.657 [eventLoopGroupProxy-4-8] INFO SleepQueryService - sleepSync(0.1) 19:50:58.767 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.772 [eventLoopGroupProxy-4-1] INFO SleepQueryService - sleepSync(0.1) 19:50:58.880 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.885 [eventLoopGroupProxy-4-2] INFO SleepQueryService - sleepSync(0.1) 19:50:58.991 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:58.995 [eventLoopGroupProxy-4-3] INFO SleepQueryService - sleepSync(0.1) 19:50:59.103 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:59.108 [eventLoopGroupProxy-4-4] INFO SleepQueryService - sleepSync(0.1) 19:50:59.219 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:59.224 [eventLoopGroupProxy-4-5] INFO SleepQueryService - sleepSync(0.1) 19:50:59.332 [eventLoopGroupProxy-4-5] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:59.336 [eventLoopGroupProxy-4-6] INFO SleepQueryService - sleepSync(0.1) 19:50:59.446 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:59.451 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 19:50:59.562 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 19:50:59.567 [eventLoopGroupProxy-4-8] INFO SleepQueryService - sleepSync(0.1) 19:50:59.677 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1
abの結果は長くなるので抜粋しますが、特に変わった点はありません。
Requests per second: 7.93 [#/sec] (mean) Time per request: 126.029 [ms] (mean) ... Percentage of the requests served within a certain time (ms) 50% 116 66% 117 75% 124 80% 124 90% 128 95% 264 98% 264 99% 264 100% 264 (longest request)
非同期エンドポイント
同様のリクエストを非同期バージョンのエンドポイントにも送ります。
$ ab -n 16 -c 1 http://localhost:8080/sleep-async/0.1
ログを確認すると、今度はクエリが DefaultDispatcher-worker-1 というスレッドで実行されています。
19:54:16.137 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.243 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.249 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.359 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.364 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.474 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.479 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.588 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.590 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.694 [eventLoopGroupProxy-4-5] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.697 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.804 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.806 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:16.950 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:16.955 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.064 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.070 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.181 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.186 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.293 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.297 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.406 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.411 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.520 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.526 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.639 [eventLoopGroupProxy-4-5] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.644 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.752 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.758 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.869 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:54:17.875 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:54:17.986 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-async/0.1
abの結果も大きく違いません。
Requests per second: 8.58 [#/sec] (mean) Time per request: 116.610 [ms] (mean) ... Percentage of the requests served within a certain time (ms) 50% 115 66% 116 75% 117 80% 117 90% 123 95% 146 98% 146 99% 146 100% 146 (longest request)
先ほどは1並列だったのでWorkerは1スレッドしか使われていませんが、次のように並列度を上げると複数のスレッドが使われます。
$ ab -n 16 -c 16 http://localhost:8080/sleep-async/0.1
19:56:20.354 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.465 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.474 [DefaultDispatcher-worker-1] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.494 [DefaultDispatcher-worker-6] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.494 [DefaultDispatcher-worker-5] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.498 [DefaultDispatcher-worker-7] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.498 [DefaultDispatcher-worker-2] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.498 [DefaultDispatcher-worker-3] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.500 [DefaultDispatcher-worker-12] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.502 [DefaultDispatcher-worker-11] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.502 [DefaultDispatcher-worker-8] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.502 [DefaultDispatcher-worker-9] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.583 [DefaultDispatcher-worker-14] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.583 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.609 [DefaultDispatcher-worker-10] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.609 [eventLoopGroupProxy-4-5] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.610 [DefaultDispatcher-worker-13] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.610 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.615 [DefaultDispatcher-worker-21] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.615 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.615 [DefaultDispatcher-worker-4] INFO SleepQueryService - sleepAsync(0.1) 19:56:20.616 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.616 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.617 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.621 [eventLoopGroupProxy-4-5] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.621 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.622 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.693 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.718 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.721 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.723 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-async/0.1 19:56:20.723 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-async/0.1
スロークエリがある場合
同期処理（クエリ）の実行時間が短い場合は大きな差が生まれませんが、実行時間が長いリクエストがあると差が生まれます。
同期バージョンのスロークエリ
1つだけ20秒かかるスロークエリがある状況を再現してみます。
$ curl http://localhost:8080/sleep-sync/20
を裏で実行した後に、abを実行します。
$ ab -n 50 -c 50 http://localhost:8080/sleep-sync/0.1
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient).....done
Server Software:
Server Hostname: localhost
Server Port: 8080
Document Path: /sleep-sync/0.1
Document Length: 3 bytes
Concurrency Level: 50
Time taken for tests: 19.255 seconds
Complete requests: 50
Failed requests: 0
Total transferred: 4100 bytes
HTML transferred: 150 bytes
Requests per second: 2.60 [#/sec] (mean)
Time per request: 19254.631 [ms] (mean)
Time per request: 385.093 [ms] (mean, across all concurrent requests)
Transfer rate: 0.21 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 3 0.9 3 4
Processing: 116 2622 6061.2 464 19137
Waiting: 112 2622 6061.2 463 19137
Total: 117 2625 6061.1 466 19138
Percentage of the requests served within a certain time (ms)
50% 466
66% 574
75% 688
80% 688
90% 18699
95% 18922
98% 19138
99% 19138
100% 19138 (longest request)
最後のリクエスト処理時間の分布を見ると、それぞれのクエリ自体は0.1秒で終わるにもかかわらず、20秒近く待たされているリクエストがあることがわかります。
ログを見ると以下のようになっており、スロークエリを処理しているのと同じスレッド eventLoopGroupProxy-4-7 に当たってしまったリクエストがスロークエリの完了を待たされています。7/8 = 87.5%のリクエストは待たされずに終わるので、リクエスト処理時間の分布において80%と90%の間に大きな差があることを説明できます。
20:14:29.031 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(20.0) 20:14:30.467 [eventLoopGroupProxy-4-8] INFO SleepQueryService - sleepSync(0.1) 20:14:30.575 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:30.583 [eventLoopGroupProxy-4-8] INFO SleepQueryService - sleepSync(0.1) 20:14:30.589 [eventLoopGroupProxy-4-6] INFO SleepQueryService - sleepSync(0.1) 20:14:30.589 [eventLoopGroupProxy-4-3] INFO SleepQueryService - sleepSync(0.1) 20:14:30.589 [eventLoopGroupProxy-4-1] INFO SleepQueryService - sleepSync(0.1) 20:14:30.589 [eventLoopGroupProxy-4-5] INFO SleepQueryService - sleepSync(0.1) 20:14:30.590 [eventLoopGroupProxy-4-4] INFO SleepQueryService - sleepSync(0.1) 20:14:30.590 [eventLoopGroupProxy-4-2] INFO SleepQueryService - sleepSync(0.1) 20:14:30.699 [eventLoopGroupProxy-4-8] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:30.699 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:30.699 [eventLoopGroupProxy-4-3] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 ... 20:14:31.266 [eventLoopGroupProxy-4-4] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:31.267 [eventLoopGroupProxy-4-2] INFO SleepQueryService - sleepSync(0.1) 20:14:31.266 [eventLoopGroupProxy-4-1] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:31.266 [eventLoopGroupProxy-4-6] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:31.375 [eventLoopGroupProxy-4-2] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:49.051 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/20 20:14:49.055 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 20:14:49.163 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:49.164 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 20:14:49.274 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:49.275 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 20:14:49.386 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:49.387 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 20:14:49.499 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:49.500 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 20:14:49.607 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1 20:14:49.608 [eventLoopGroupProxy-4-7] INFO SleepQueryService - sleepSync(0.1) 20:14:49.717 [eventLoopGroupProxy-4-7] INFO ktor.application - 200 OK: GET - /sleep-sync/0.1
非同期バージョンのスロークエリ
非同期バージョンのスロークエリを裏で実行した場合は、他のリクエストがスロークエリに待たされることはなく、短時間で完了します。
$ curl http://localhost:8080/sleep-async/20
$ ab -n 50 -c 50 http://localhost:8080/sleep-async/0.1
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient).....done
Server Software:
Server Hostname: localhost
Server Port: 8080
Document Path: /sleep-async/0.1
Document Length: 3 bytes
Concurrency Level: 50
Time taken for tests: 0.810 seconds
Complete requests: 50
Failed requests: 0
Total transferred: 4100 bytes
HTML transferred: 150 bytes
Requests per second: 61.75 [#/sec] (mean)
Time per request: 809.659 [ms] (mean)
Time per request: 16.193 [ms] (mean, across all concurrent requests)
Transfer rate: 4.95 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 4 2.0 4 8
Processing: 123 374 182.4 354 686
Waiting: 115 374 182.6 354 686
Total: 123 378 181.6 357 689
Percentage of the requests served within a certain time (ms)
50% 357
66% 472
75% 578
80% 581
90% 583
95% 687
98% 689
99% 689
100% 689 (longest request)
結論
結論としては、次の通りです。
Ktor Serverにおいて、リクエストを処理するスレッドはラウンドロビンで順番に割り当てられるので、時間のかかる同期処理があると、後続のリクエストが同期処理の完了を待たされてしまう。
最後に、Ktor Serverにおける同期処理への向き合い方を的確に表す質問への回答があったので、引用しておきます。
Ktor, how to deal with jdbc blocking calls - Kotlin Discussions
- If operations are fast and you are sure that they won’t block forever, you can call them inside coroutines.
- If operations are long, but you have only few of them, you can use custom CoroutineContext with increased number of parallel threads.
- If you have a large number of those blocking operations, you should just good old executor. If you want to evaluate the result, you can create a Channel and send results to it.
-
参考: https://yakubouzu.hatenablog.com/entry/2020/07/24/114509↩
-
スレッド数は、callGroupSize という設定で変更でき、デフォルト値は
Runtime.getRuntime().availableProcessors()（利用可能なコア数）です。↩
