はじめに
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処理を用意する。
[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
つまり処理が始まる前か終わった後の待ちが長いことがわかる。
これは何に待たされているのかを調べると、スレッドプールにスレッドを追加するのが待たされていることがわかった。
スレッドプールの説明はこちら
マネージドスレッドプール
ASP.NETによらず、.NET環境ではスレッドはプロセス自身が立ち上げて管理するより、タスクを使ってスレッドプールのスレッドを使い回すことが推奨されている。スレッドプールにはいくつかのスレッドが待機しており、タスク(ASP.NETではHTTPリクエストなど)がキューに入ると、空いているスレッドに割り当て、処理が終わると待機状態に戻す、という処理がされている。
ここで問題なのは、どの程度のスレッドがプールされるのか、ということだが、以下に記載されている。
スレッドプールでは、カテゴリごとに指定された最小値に達するまで、要求に応じて新しいワーカースレッドまたは I/O完了スレッドが提供されます。
スレッドプールの最小値に達すると、追加のスレッドが作成されるか、いくつかのタスクが完了するまで待機状態になります。 .NET Framework 4 以降では、スループットを最適化するために、スレッドプールでワーカースレッドの作成と破棄が行われます。スループットは、タスクの単位時間あたりの完了数として定義されます。
まとめるとこんな感じ。
- スレッドが即起動されるのは指定した最小値まで
- 最小値以上の個数のスレッドは作成が待たされる
- タスクの単位時間のあたりの完了数が最適になるように生成は調整される
スレッドは決まった数まではすぐに立ち上がるけど、それ以降は他の処理が終わるか、.NETの実行環境によって新しくスレッドが生成されるまで待たされるということ。
この決まった数というのは、ThreadPool.GetMinThreadsメソッドで取得できる。Macで確認すると、
ワーカースレッド：4
IO待ち:4
だった。これは既定では、スレッドの最小数はシステム上のプロセッサの数に設定されます。と書かれているようにCPUの数であり、他の環境で確認してもvCPUの数であった。vCPUが2のサーバーだと、即起動されるスレッドは2個まで、ということになる。スレッド2個とか少ないのでは？
以下のコードで処理が開始された時間とスレッドIDをログに出して確認してみる。
[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メソッドを使う。
とりあえず以下のようにワーカースレッドの最低数を100にしてみる。
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秒で終了した。このことからも、やはり同時アクセス時の応答が遅くなるのは、スレッドの立ち上げが待たされているためだということがわかった。とはいえ以下の注意書きにもあるように、むやみにスレッド数を増やすのもよくないかもしれない。
アイドルスレッドの最小数は、ThreadPool.SetMinThreads メソッドを使用して増やすことができます。 ただし、これらの値を必要以上に大きくすると、パフォーマンスの問題が発生する可能性があります。 同時に開始するタスクの数が多すぎる場合は、すべてのタスクで処理速度が低下する可能性があります。 ほとんどの場合、スレッドを割り当てるためのスレッド プール独自のアルゴリズムを使用することでスレッドプールのパフォーマンスが向上します。
IO同期待ちの場合
IO待ちの場合も見てみよう。
先ほどの1秒待って応答するAPI(http://localhost:5001 で待ち受けさせる)に対してリクエストするAPIを以下のように書く。非同期メソッドGetAsyncをResultで同期的に待つようにする。
[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で非同期に待って処理させるようにする。以下のようになる。
[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とし、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待ちに関する記事を読むと、IOの結果を待っている間にスレッドは存在しないとのこと。処理がawait client.GetAsyncにまでたどり着けばその時点でスレッドは解放され、次のスレッドを生成することができる。(Resultで待つようなことをしているとスレッドは解放されないものと思われる)
そして非同期待ちが終わると、その時点で処理がスレッドに割り当てられて処理が再開されるが、この時もスレッドは使われていないのでスレッドプールにある少数のスレッドを割り当てることができる。APIアクセスやDBアクセスなどIO待ちがメインの処理の場合は、awaitで呼び出すと少数のスレッドで多数のリクエストをさばけるようになる。基本的にはこの形で作るべきと思われる。
おわりに
スレッド、スレッドプール、タスク、async/awaitなど、C#や.NET Coreの非同期処理の勉強になった。
async/awaitは一見何やってるかわからないけど、わかればすごく便利。使えるところでは積極的に使っていこう。