Kotlin コルーチンでノンブロッキングなHttpRequestの夢を見る

はじめに

これを書いてたら自分よりもちゃんとした記事が公開されていました。
なので手っ取り早く且つ詳細な情報はこちらをご覧ください
Kotlin コルーチンでネットワーク I/O 処理実験 - Qiita

他にも似たようなことやってる方がいたので、いい流れだなと思ってます。誰か私にベストプラクティスを示してください。
それはそれとして途中まで書いてしまったのでこの記事も投稿。

期待してること

複数のHttp Requestを投げてResponse待ちの間はスレッドをブロックせずに動いてくれたら言う事なしだなと思い、詳しく調べるより先にとりあえずやってみました。

覚えたての知識で試してみた。

お試し

環境はSpring boot + kotlinでokhttpを使用しています。
ご覧の通り200回ほどリクエストを投げる形になっています。

main.kt

fun main(args: Array<String>) = runBlocking {
  val log = logger()

  val client = OkHttpClient().newBuilder()
      .connectTimeout(50, TimeUnit.SECONDS)
      .readTimeout(50, TimeUnit.SECONDS)
      .build()

  for (I in 1..200) {
    launch {
      runCatching {
        withContext(Dispatchers.IO) {
          log.info("req start $I")
          val req = Request.Builder().url("https://httpbin.org/delay/10").build() // 10秒後にレスポンスする
          client.newCall(req).execute()
        }
      }.fold(
          onSuccess = {
            val result = it
            log.info("req end = $I / result = $result")
          },
          onFailure = {
            log.info("req failure = $I / result = $it")
          }
      )
    }
  }
}

レスポンスが来るまで10秒を指定してるので、ここで期待通りレスポンス待ちの間に「スレッドを止めずに」別のCoroutineが動いてくれればいいわけです。つまりレスポンス待ちのCoroutineが使用しているスレッドをブロックしなければ200のリクエストが一気に発行されるはずです。

結果

log.txt

19-02-20 11:18:57.976 INFO  1808 [DefaultDispatcher-worker-65] || - req start 58
19-02-20 11:18:57.976 INFO  1808 [DefaultDispatcher-worker-58] || - req start 59
19-02-20 11:18:57.977 INFO  1808 [DefaultDispatcher-worker-53] || - req start 60
19-02-20 11:18:57.977 INFO  1808 [DefaultDispatcher-worker-16] || - req start 61
19-02-20 11:18:57.978 INFO  1808 [DefaultDispatcher-worker-69] || - req start 62
19-02-20 11:18:57.978 INFO  1808 [DefaultDispatcher-worker-70] || - req start 63
19-02-20 11:18:57.978 INFO  1808 [DefaultDispatcher-worker-52] || - req start 64
19-02-20 11:19:09.118 INFO  1808 [main] || - req end = 47 / result = Response{protocol=http/1.1, code=200, message=OK, url=https://httpbin.org/delay/10}
19-02-20 11:19:09.118 INFO  1808 [DefaultDispatcher-worker-54] || - req start 66
19-02-20 11:19:09.118 INFO  1808 [DefaultDispatcher-worker-16] || - req start 65

Coroutineの実行順序は保証されていませんが、今回はほぼ順番に実行されていたと思ってください。
一度に64個のCoroutineからリクエストが投げられましたが、結局それ以上は動きませんでした。以降はレスポンスを受け取ってから次のCoroutineがスタートされるといった動きでした。
ということはDispatchers.IOが持っているThreadPoolのスレッドをブロッキングして使い切り、空いたスレッドが次のCoroutineを実行しているということです。

なぜ64個なのか？

前職の同僚に教えていただいたのですが、Dispatchers.IOは「有効なCPUの数 * 64」の数のスレッドを持つThreadPoolでCoroutineを実行するとのこと(この言い方で合っているかはともかく)。

というわけでレスポンスを待ってる間に別のCoroutineを実行してくれるわけではないようです。
まあ考えてみれば当たり前だよなということでした。

ちなみにクアッドコアのMacを使ってるのですが、有効なCPUが１つなのはなんでだったのでしょう？結局調べられてない。

Ktor Clientでやってみる

冒頭で紹介した方の記事に、ktorでノンブロッキングなrequestができたと記載されていました。Spring bootでktor client使えるのかなという確認のためにも期待しつつ試してみました。

お試し

• gradleに以下を追加

build.gradle

dependencies {
    implementation "io.ktor:ktor-client-apache:$ktor_version"
}

• 実行コード

main.kt

fun main(args: Array<String>) = runBlocking {
      val log = logger()
    log.info("start")

    val client = HttpClient(Apache)

    for (I in 1..200) {
      launch {
        runCatching {
          withContext(Dispatchers.IO) {
            log.info("req start $I")
            client.get<String>(scheme = "https", host = "httpbin.org", path = "/delay/5", port = 443) // 5秒後にレスポンスする
          }

        }.fold(
            onSuccess = {
              log.info("req end = $I")
            },
            onFailure = {
              log.info("req failure = $I / result = $it")
            }
        )
      }
    }

    log.info("end")
  }

結果

ノンブロッキングなHttpRequestの夢が叶ってしまいました。
ほぼ同時に200のリクエストを送り、レスポンスも誤差1000msec強で200個が返ってきました。
かなりの衝撃を受けました。内部的にどうやって実現してるのか気になるところですが、今回は夢がかなったのでここまで。

※2019/2/27追記

• Thread dump取ってみました

実行前

Threads class SMR info:
_java_thread_list=0x00007fcd6abab3b0, length=19, elements={
0x00007fcd6c005000, 0x00007fcd6c02b800, 0x00007fcd6c828000, 0x00007fcd6b861000,
0x00007fcd6b862000, 0x00007fcd6b863000, 0x00007fcd6b864000, 0x00007fcd6b867800,
0x00007fcd6b868000, 0x00007fcd6d070800, 0x00007fcd6c81b800, 0x00007fcd6c9cf000,
0x00007fcd6b897800, 0x00007fcd6b072000, 0x00007fcd6ca08000, 0x00007fcd6ca7f800,
0x00007fcd6d16c000, 0x00007fcd6d16d000, 0x00007fcd6c030000
}

実行後

_java_thread_list=0x00007fcd6975a5e0, length=34, elements={
0x00007fcd6c005000, 0x00007fcd6c02b800, 0x00007fcd6c828000, 0x00007fcd6b861000,
0x00007fcd6b862000, 0x00007fcd6b863000, 0x00007fcd6b864000, 0x00007fcd6b867800,
0x00007fcd6b868000, 0x00007fcd6d070800, 0x00007fcd6c81b800, 0x00007fcd6c9cf000,
0x00007fcd6b897800, 0x00007fcd6b072000, 0x00007fcd6ca08000, 0x00007fcd6ca7f800,
0x00007fcd6d16c000, 0x00007fcd6d16d000, 0x00007fcd6c030000, 0x00007fcd6babb800,
0x00007fcd6d24c000, 0x00007fcd6bb0f000, 0x00007fcd6d2c2800, 0x00007fcd6cbfa000,
0x00007fcd6bb1c800, 0x00007fcd6bb1d800, 0x00007fcd6bb16000, 0x00007fcd699b4800,
0x00007fcd699e3800, 0x00007fcd699e4000, 0x00007fcd6d2d1800, 0x00007fcd69a52800,
0x00007fcd6bb17800, 0x00007fcd6d29b000
}

15個ほどThreadが増えています。Ktor内部でThread起ち上げてますが、200 requestで15Threadだったら上々ですね。

別件でKtorに設定しているconfig(タイムアウト設定など)を変えたくて、configを上書きしていたらThreadが一瞬500以上生成されてしまったのでこれはまた別で追記します。