ASP.NET Coreへの同時アクセス時の応答が遅くなるのはスレッドプールの挙動のためかも

# はじめに

ASP.NET Coreへの同時アクセスの応答が妙に遅くなるので原因調査したら、スレッドプールの起動の問題、もっと言えば.NET環境での非同期処理の使い方の問題だったので、メモしておく。

# 実験環境

macOS 10.16.6
ASP.NET Core 3.1
`dotnet new webapi` コマンドで作成したWeb API
`ab -n 100 -c 100 URL` ab(Apache Bench)コマンドで同時100アクセスの時間を計測

# 同期処理の場合

以下の単純なAPI処理を用意する。

```csharp
[HttpGet]
[Route("sync")]
public string Sync()
{
    Stopwatch sw = new Stopwatch();
    sw.Start();
    Thread.Sleep(1000);
    sw.Stop();
    this._logger.LogInformation(sw.ElapsedMilliseconds + "ms");
    return "sync";
}
```

1秒スリープなので1秒で応答が帰ってくるはず。

結果

```
ab -n 100 -c 100 http://localhost:5000/test/sync
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
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:        Kestrel
Server Hostname:        localhost
Server Port:            5000

Document Path:          /test/sync
Document Length:        4 bytes

Concurrency Level:      100
Time taken for tests:   15.031 seconds
Complete requests:      100
Failed requests:        39
   (Connect: 0, Receive: 0, Length: 39, Exceptions: 0)
Total transferred:      8357 bytes
HTML transferred:       244 bytes
Requests per second:    6.65 [#/sec] (mean)
Time per request:       15031.445 [ms] (mean)
Time per request:       150.314 [ms] (mean, across all concurrent requests)
Transfer rate:          0.54 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    5   1.8      5       8
Processing:  1020 11970 2007.4  13046   14009
Waiting:        0 7868 6438.3  13046   14009
Total:       1020 11975 2006.7  13050   14011

Percentage of the requests served within a certain time (ms)
  50%  13050
  66%  13052
  75%  13053
  80%  13053
  90%  13055
  95%  13100
  98%  13943
  99%  14011
 100%  14011 (longest request)
```

最悪で14秒。遅い。一方ログを見ると各処理は1秒で終わっていることがわかる。

```
1004ms
1003ms
...
1000ms
1004ms
```

つまり処理が始まる前か終わった後の待ちが長いことがわかる。
これは何に待たされているのかを調べると、スレッドプールにスレッドを追加するのが待たされていることがわかった。

スレッドプールの説明はこちら
[マネージドスレッドプール](https://docs.microsoft.com/ja-jp/dotnet/standard/threading/the-managed-thread-pool)

ASP.NETによらず、.NET環境ではスレッドはプロセス自身が立ち上げて管理するより、タスクを使ってスレッドプールのスレッドを使い回すことが推奨されている。スレッドプールにはいくつかのスレッドが待機しており、タスク(ASP.NETではHTTPリクエストなど)がキューに入ると、空いているスレッドに割り当て、処理が終わると待機状態に戻す、という処理がされている。

ここで問題なのは、どの程度のスレッドがプールされるのか、ということだが、以下に記載されている。

[スレッドプールの最小値](https://docs.microsoft.com/ja-jp/dotnet/standard/threading/the-managed-thread-pool#thread-pool-minimums)
> スレッドプールでは、カテゴリごとに指定された最小値に達するまで、要求に応じて新しいワーカースレッドまたは I/O完了スレッドが提供されます。
> スレッドプールの最小値に達すると、追加のスレッドが作成されるか、いくつかのタスクが完了するまで待機状態になります。 .NET Framework 4 以降では、スループットを最適化するために、スレッドプールでワーカースレッドの作成と破棄が行われます。スループットは、タスクの単位時間あたりの完了数として定義されます。

まとめるとこんな感じ。

- スレッドが即起動されるのは指定した最小値まで
- 最小値以上の個数のスレッドは作成が待たされる
- タスクの単位時間のあたりの完了数が最適になるように生成は調整される

スレッドは決まった数まではすぐに立ち上がるけど、それ以降は他の処理が終わるか、.NETの実行環境によって新しくスレッドが生成されるまで待たされるということ。

この決まった数というのは、[ThreadPool.GetMinThreadsメソッド](https://docs.microsoft.com/ja-jp/dotnet/api/system.threading.threadpool.getminthreads?view=netcore-3.1)で取得できる。Macで確認すると、

ワーカースレッド：4
IO待ち:4

だった。これは`既定では、スレッドの最小数はシステム上のプロセッサの数に設定されます。`と書かれているようにCPUの数であり、他の環境で確認してもvCPUの数であった。vCPUが2のサーバーだと、即起動されるスレッドは2個まで、ということになる。スレッド2個とか少ないのでは？

以下のコードで処理が開始された時間とスレッドIDをログに出して確認してみる。

```csharp
[HttpGet]
[Route("sync")]
public string Sync()
{
    var startTime = DateTimeOffset.Now;
    Stopwatch sw = new Stopwatch();
    sw.Start();
    Thread.Sleep(1000);
    sw.Stop();
    this._logger.LogInformation("{0,2}: {1:D2}:{2:D2}:{3:D2}:{4:D3} {5,5}ms",  Thread.CurrentThread.ManagedThreadId, startTime.Hour, startTime.Minute, startTime.Second, startTime.Millisecond, sw.ElapsedMilliseconds);
    return "sync";
}
```

結果はこちら。カッコでほぼ同じ時間に起動したスレッドの数を追記した。

```
   9: 18:31:40:893  1000ms (1個)
   9: 18:31:41:912  1004ms
   8: 18:31:41:912  1004ms
   4: 18:31:41:911  1004ms
  11: 18:31:41:912  1004ms
   6: 18:31:41:917  1004ms (5個)
  12: 18:31:42:907  1001ms
   4: 18:31:42:918  1000ms
   8: 18:31:42:918  1000ms
  11: 18:31:42:918  1000ms
   9: 18:31:42:919  1000ms
   6: 18:31:42:921  1004ms (6個)
   4: 18:31:43:919  1004ms
   8: 18:31:43:919  1004ms
  11: 18:31:43:919  1004ms
   9: 18:31:43:919  1004ms
   6: 18:31:43:926  1004ms (5個)
   4: 18:31:44:942  1003ms
  11: 18:31:44:943  1003ms
   9: 18:31:44:942  1003ms
   6: 18:31:44:945  1004ms
   8: 18:31:44:944  1004ms
  12: 18:31:44:958  1000ms (6個)
  13: 18:31:45:933  1004ms
   8: 18:31:45:956  1004ms
   9: 18:31:45:956  1005ms
  11: 18:31:45:958  1003ms
   6: 18:31:45:957  1003ms
  12: 18:31:45:961  1003ms
   4: 18:31:45:985  1001ms (7個)
  13: 18:31:46:940  1002ms
  14: 18:31:46:961  1004ms
   6: 18:31:46:968  1003ms
  11: 18:31:46:968  1003ms
  12: 18:31:46:968  1003ms
   9: 18:31:46:968  1004ms
   4: 18:31:46:988  1001ms
   8: 18:31:46:992  1003ms (8個)
  15: 18:31:47:940  1002ms
  13: 18:31:47:944  1004ms
  14: 18:31:47:968  1004ms
   6: 18:31:47:977  1004ms
   9: 18:31:47:979  1004ms
  12: 18:31:47:980  1003ms
   4: 18:31:47:990  1004ms
   8: 18:31:47:996  1004ms
  11: 18:31:48:078  1002ms (9個)
  13: 18:31:48:950  1000ms
  14: 18:31:48:973  1002ms
   6: 18:31:48:982  1003ms
  12: 18:31:48:984  1002ms
   9: 18:31:48:984  1003ms
   4: 18:31:48:995  1001ms
   8: 18:31:49:001  1004ms
  15: 18:31:49:081  1003ms
  11: 18:31:49:081  1003ms (9個)
  13: 18:31:49:951  1003ms
  16: 18:31:49:953  1003ms
  14: 18:31:49:977  1004ms
   6: 18:31:49:985  1004ms
   9: 18:31:49:987  1004ms
  12: 18:31:49:987  1004ms
   4: 18:31:49:997  1000ms
   8: 18:31:50:006  1000ms
  15: 18:31:50:085  1003ms
  11: 18:31:50:085  1003ms (10個)
  16: 18:31:50:957  1001ms
  14: 18:31:50:981  1004ms
   6: 18:31:50:990  1004ms
   9: 18:31:50:992  1004ms
  12: 18:31:50:992  1004ms
   4: 18:31:50:998  1004ms
   8: 18:31:51:007  1005ms
  13: 18:31:51:015  1003ms
  15: 18:31:51:089  1000ms
  11: 18:31:51:089  1000ms (10個)
  16: 18:31:51:962  1004ms
  14: 18:31:51:987  1001ms
   6: 18:31:51:995  1003ms
  12: 18:31:51:997  1003ms
   9: 18:31:51:996  1003ms
   4: 18:31:52:003  1002ms
  13: 18:31:52:021  1001ms
   8: 18:31:52:021  1001ms
  11: 18:31:52:090  1001ms
  15: 18:31:52:090  1001ms (10個)
  16: 18:31:52:967  1005ms
  14: 18:31:52:989  1002ms
   6: 18:31:52:999  1004ms
   9: 18:31:53:000  1004ms
  12: 18:31:53:000  1004ms
   4: 18:31:53:006  1003ms
   8: 18:31:53:026  1000ms
  13: 18:31:53:026  1000ms
  11: 18:31:53:092  1003ms
  15: 18:31:53:092  1003ms
  17: 18:31:53:092  1003ms (11個)
  16: 18:31:53:972  1002ms
  14: 18:31:53:992  1000ms
   6: 18:31:54:003  1000ms (3個)
```

徐々に使えるスレッドが増えていっている、というか徐々にしかスレッド数が増えないのがわかる。

# 最低スレッド数を上げる

一番簡単な解決策としては即立ち上げられるスレッドの個数を増やせばよい。
そのためには、[ThreadPool.SetMinThreadsメソッド](https://docs.microsoft.com/ja-jp/dotnet/api/system.threading.threadpool.setminthreads?view=netcore-3.1)を使う。
とりあえず以下のようにワーカースレッドの最低数を100にしてみる。

```csharp
public static void Main(string[] args)
{
    ThreadPool.SetMinThreads(100, 4);
    CreateHostBuilder(args).Build().Run();
}
```

abコマンドを実行すると、

```
ab -n 100 -c 100 http://localhost:5000/test/sync
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
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:        Kestrel
Server Hostname:        localhost
Server Port:            5000

Document Path:          /test/sync
Document Length:        4 bytes

Concurrency Level:      100
Time taken for tests:   2.082 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      13700 bytes
HTML transferred:       400 bytes
Requests per second:    48.04 [#/sec] (mean)
Time per request:       2081.569 [ms] (mean)
Time per request:       20.816 [ms] (mean, across all concurrent requests)
Transfer rate:          6.43 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0   11   3.0     12      13
Processing:  1020 1055   5.1   1056    1061
Waiting:     1007 1054   6.3   1055    1060
Total:       1020 1066   7.0   1068    1074

Percentage of the requests served within a certain time (ms)
  50%   1068
  66%   1069
  75%   1070
  80%   1070
  90%   1072
  95%   1073
  98%   1073
  99%   1074
 100%   1074 (longest request)
```

ほぼ1秒で終了した。このことからも、やはり同時アクセス時の応答が遅くなるのは、スレッドの立ち上げが待たされているためだということがわかった。とはいえ以下の注意書きにもあるように、むやみにスレッド数を増やすのもよくないかもしれない。

[スレッドプールの最小値](https://docs.microsoft.com/ja-jp/dotnet/standard/threading/the-managed-thread-pool#thread-pool-minimums)
> アイドルスレッドの最小数は、ThreadPool.SetMinThreads メソッドを使用して増やすことができます。 ただし、これらの値を必要以上に大きくすると、パフォーマンスの問題が発生する可能性があります。 同時に開始するタスクの数が多すぎる場合は、すべてのタスクで処理速度が低下する可能性があります。 ほとんどの場合、スレッドを割り当てるためのスレッド プール独自のアルゴリズムを使用することでスレッドプールのパフォーマンスが向上します。

# IO同期待ちの場合

IO待ちの場合も見てみよう。
先ほどの1秒待って応答するAPI(http://localhost:5001 で待ち受けさせる)に対してリクエストするAPIを以下のように書く。非同期メソッドGetAsyncをResultで同期的に待つようにする。

```csharp
[HttpGet]
[Route("io")]
public string Io()
{
    var startTime = DateTimeOffset.Now;
    Stopwatch sw = new Stopwatch();
    sw.Start();
    var response = client.GetAsync("http://localhost:5001/test/sync").Result;
    sw.Stop();
    this._logger.LogInformation("{0,2}: {1:D2}:{2:D2}:{3:D2}:{4:D3} {5,5}ms",  Thread.CurrentThread.ManagedThreadId, startTime.Hour, startTime.Minute, startTime.Second, startTime.Millisecond, sw.ElapsedMilliseconds);
    return "iosy";
}
```

これをワーカースレッド4、IO待ちスレッド4で起動させて、同じくabで同時100アクセスするとどうなるか。

```
ab -n 100 -c 100 -s 300 http://localhost:5000/test/io
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
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:        Kestrel
Server Hostname:        localhost
Server Port:            5000

Document Path:          /test/io
Document Length:        4 bytes

Concurrency Level:      100
Time taken for tests:   65.697 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      13700 bytes
HTML transferred:       400 bytes
Requests per second:    1.52 [#/sec] (mean)
Time per request:       65696.601 [ms] (mean)
Time per request:       656.966 [ms] (mean, across all concurrent requests)
Transfer rate:          0.20 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    5   1.5      6       7
Processing:  1021 63970 6359.5  64624   64674
Waiting:     1014 63970 6360.2  64623   64674
Total:       1022 63975 6360.0  64630   64681

Percentage of the requests served within a certain time (ms)
  50%  64630
  66%  64640
  75%  64642
  80%  64648
  90%  64662
  95%  64673
  98%  64675
  99%  64681
 100%  64681 (longest request)
```

めっちゃくちゃ遅くなった。abのデフォルトタイムアウト30秒では足りないのでタイムアウト時間を伸ばさないといけなかったほど。ログはこんな感じになる(開始時間順に並べ直している)

```
   6: 21:09:51:730  1080ms
  11: 21:09:54:925  1006ms
   4: 21:09:55:949 63195ms
   6: 21:09:55:949 63129ms
   8: 21:09:55:949 62054ms
   9: 21:09:55:949 63110ms
  11: 21:09:55:954 63080ms
  12: 21:09:57:038 62084ms
  13: 21:09:57:540 61490ms
  14: 21:09:58:050 61037ms
  15: 21:09:59:057 59987ms
  16: 21:10:00:068 58999ms
  17: 21:10:01:073 58031ms
  18: 21:10:01:581 57523ms
  19: 21:10:02:584 56543ms
  20: 21:10:03:589 55471ms
  21: 21:10:04:607 54465ms
  22: 21:10:05:610 53450ms
  23: 21:10:06:616 52488ms
  24: 21:10:07:613 51514ms
  25: 21:10:08:620 50446ms
  26: 21:10:09:127 49940ms
  27: 21:10:10:145 48959ms
  28: 21:10:11:151 47928ms
  29: 21:10:12:147 46873ms
  30: 21:10:13:151 45952ms
  31: 21:10:13:658 45388ms
  32: 21:10:14:662 44427ms
  33: 21:10:15:665 43401ms
  34: 21:10:16:170 42933ms
  35: 21:10:16:678 42382ms
  36: 21:10:17:184 41877ms
  37: 21:10:17:685 41405ms
  38: 21:10:18:200 40873ms
  39: 21:10:19:223 39843ms
  40: 21:10:20:260 38832ms
  41: 21:10:21:219 37814ms
  42: 21:10:21:722 37305ms
  43: 21:10:22:227 36798ms
  44: 21:10:22:729 36313ms
  45: 21:10:23:284 35757ms
  46: 21:10:24:291 34757ms
  47: 21:10:25:298 33782ms
  48: 21:10:26:288 32781ms
  49: 21:10:27:264 31802ms
  50: 21:10:28:267 30822ms
  51: 21:10:28:769 30322ms
  52: 21:10:29:271 29777ms
  53: 21:10:29:776 29286ms
  54: 21:10:30:282 28779ms
  55: 21:10:30:787 28279ms
  56: 21:10:31:292 27757ms
  57: 21:10:31:797 27272ms
  58: 21:10:32:302 26748ms
  59: 21:10:32:808 26290ms
  60: 21:10:33:321 25733ms
  61: 21:10:34:337 24696ms
  62: 21:10:35:329 23731ms
  63: 21:10:35:834 23264ms
  64: 21:10:36:337 22761ms
  65: 21:10:36:841 22256ms
  66: 21:10:37:346 21757ms
  67: 21:10:37:851 21213ms
  68: 21:10:38:356 20671ms
  69: 21:10:38:860 20202ms
  70: 21:10:39:361 19700ms
  71: 21:10:39:866 19208ms
  72: 21:10:40:370 18694ms
  73: 21:10:40:871 18244ms
  74: 21:10:41:376 17740ms
  75: 21:10:41:877 17238ms
  76: 21:10:42:879 16245ms
  77: 21:10:43:381 15650ms
  78: 21:10:43:885 15195ms
  79: 21:10:44:390 14671ms
  80: 21:10:44:894 14229ms
  81: 21:10:45:398 13730ms
  82: 21:10:45:903 13225ms
  83: 21:10:46:408 12634ms
  84: 21:10:46:913 12210ms
  85: 21:10:47:418 11649ms
  86: 21:10:47:920 11154ms
  87: 21:10:48:422 10635ms
  88: 21:10:48:933 10199ms
  89: 21:10:49:433  9699ms
  90: 21:10:49:938  9195ms
  91: 21:10:50:443  8689ms
  92: 21:10:50:948  8142ms
  93: 21:10:51:453  7640ms
  94: 21:10:51:956  7183ms
  95: 21:10:52:460  6644ms
  96: 21:10:52:965  6052ms
  97: 21:10:53:470  5670ms
  98: 21:10:53:972  5143ms
  99: 21:10:54:477  4592ms
 100: 21:10:54:982  4158ms
 101: 21:10:55:486  3654ms
 102: 21:10:55:990  3155ms
 103: 21:10:56:492  2541ms
 104: 21:10:56:997  2149ms
 105: 21:10:57:501  1644ms
```

スレッドが500msもしくは1秒ごとに1個生成されて、ほぼ100個のスレッドが生成され(正確には98個)、ほぼ同じ時間に終了している。http://localhost:5000/test/io へのアクセスは徐々に処理されているが、http://localhost:5001/test/sync にはほぼ同じ時間にアクセスが届いている。

IO待ちスレッドを100に増やしても同程度。ワーカースレッドを100にすると1秒になった。

アクセス時にスレッドプールのキューに100個溜まって、それを処理するスレッドが順次生成されているが、それが全部消化されるまではIO処理に入っていない感じになっている。正確にはよくわからないが、WaitやResultで待つ処理はワーカースレッドのキューに入り、それが割り当てられない限りは非同期部分の処理にも進めないのかもしれない。この場合も想定される同時リクエスト数分のワーカースレッド数を設定しないとさばけないだろう。結果としては最悪なので、非同期処理を同期的に待つ、というのはあまりやらない方がよさそう。

# IO非同期待ちの場合

ということでawaitで非同期に待って処理させるようにする。以下のようになる。

```csharp
[HttpGet]
[Route("asyncio")]
public async Task<string> AsyncIo()
{
    var startTime = DateTimeOffset.Now;
    Stopwatch sw = new Stopwatch();
    sw.Start();
    var response = await client.GetAsync("http://localhost:5001/test/sync");
    sw.Stop();
    this._logger.LogInformation("{0,2}: {1:D2}:{2:D2}:{3:D2}:{4:D3} {5,5}ms",  Thread.CurrentThread.ManagedThreadId, startTime.Hour, startTime.Minute, startTime.Second, startTime.Millisecond, sw.ElapsedMilliseconds);
    return "ioas";
}
```

コントローラのメソッドにasyncをつけ、戻り値の型をTask<string>とし、GetAsyncをawaitで待つ。

これまでと同様、ワーカースレッド4、IO待ちスレッド4として起動し、abで同時100アクセスした。

```
ab -n 100 -c 100 http://localhost:5000/test/asyncio
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
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:        Kestrel
Server Hostname:        localhost
Server Port:            5000

Document Path:          /test/asyncio
Document Length:        4 bytes

Concurrency Level:      100
Time taken for tests:   2.206 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      13700 bytes
HTML transferred:       400 bytes
Requests per second:    45.32 [#/sec] (mean)
Time per request:       2206.289 [ms] (mean)
Time per request:       22.063 [ms] (mean, across all concurrent requests)
Transfer rate:          6.06 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    5   2.0      4       9
Processing:  1015 1149  26.1   1156    1165
Waiting:     1015 1148  26.6   1155    1164
Total:       1023 1153  25.5   1159    1169

Percentage of the requests served within a certain time (ms)
  50%   1159
  66%   1162
  75%   1164
  80%   1164
  90%   1166
  95%   1167
  98%   1168
  99%   1169
 100%   1169 (longest request)
```

スレッド数が少なくても、ほぼ1秒で処理できたことがわかる。ASP.NET Core的にはこれが正解なんだろうと思う。

[IO待ちに関する記事](https://blog.stephencleary.com/2013/11/there-is-no-thread.html)を読むと、IOの結果を待っている間にスレッドは存在しないとのこと。処理がawait client.GetAsyncにまでたどり着けばその時点でスレッドは解放され、次のスレッドを生成することができる。(Resultで待つようなことをしているとスレッドは解放されないものと思われる)

そして非同期待ちが終わると、その時点で処理がスレッドに割り当てられて処理が再開されるが、この時もスレッドは使われていないのでスレッドプールにある少数のスレッドを割り当てることができる。APIアクセスやDBアクセスなどIO待ちがメインの処理の場合は、awaitで呼び出すと少数のスレッドで多数のリクエストをさばけるようになる。基本的にはこの形で作るべきと思われる。

# おわりに

スレッド、スレッドプール、タスク、async/awaitなど、C#や.NET Coreの非同期処理の勉強になった。
async/awaitは一見何やってるかわからないけど、わかればすごく便利。使えるところでは積極的に使っていこう。