如何正确测量 ASP.NET Core 请求持续时间？
Dar*_*agh 7 asp.net asp.net-core
给出以下最基本的 ASP.NET Core 应用程序（注意 Thread.Sleep）：
public class Program
{
public static void Main(string[] args)
{
CreateHostBuilder(args).Build().Run();
}
public static IHostBuilder CreateHostBuilder(string[] args) =>
Host.CreateDefaultBuilder(args)
.ConfigureWebHostDefaults(webBuilder =>
{
webBuilder.Configure(appBuilder =>
appBuilder.Run(async context =>
{
var stopwatch = Stopwatch.StartNew();
Thread.Sleep(1000);
await context.Response.WriteAsync($"Finished in {stopwatch.ElapsedMilliseconds} milliseconds.");
}));
});
}
以及以下 appsettings.json
{
"Logging": {
"LogLevel": {
"Default": "None",
"Microsoft.AspNetCore.Hosting.Diagnostics" : "Information",
}
},
"AllowedHosts": "*"
}
如果我运行中等负载测试（100 个请求，在我的例子中使用庞巴迪），我会看到大约 5 秒的延迟。
~/go/bin/bombardier http://localhost:5000 -l -n 100 -t 60s
Bombarding http://localhost:51568 with 100 request(s) using 125 connection(s)
100 / 100 [=================================================================================================================================] 100.00% 16/s 6s
Done!
Statistics Avg Stdev Max
Reqs/sec 19.46 250.28 4086.58
Latency 5.21s 366.21ms 6.05s
Latency Distribution
50% 5.05s
75% 5.05s
90% 6.04s
95% 6.05s
99% 6.05s
HTTP codes:
1xx - 0, 2xx - 100, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 3.31KB/s
但是，我在日志中看到的只是
信息：Microsoft.AspNetCore.Hosting.Diagnostics[2] 请求在 1003.3658ms 200 内完成
显然，请求花费的时间超过 1 秒。我相信未计算的 4 秒是请求在 ThreadPool 上排队时的时间。
所以我的问题是如何从应用程序内部测量此延迟？
我在我的环境中运行了您的应用程序，ASP.NET 日志与您的非常相似：
\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1022.4689ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1004.1694ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1003.4582ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1004.3703ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1003.3915ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1004.3106ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1003.122ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1017.028ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1004.2742ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1006.5832ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1004.9214ms 200\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[1]\n Request starting HTTP/1.1 GET http://localhost:5000/\ninfo: Microsoft.AspNetCore.Hosting.Diagnostics[2]\n Request finished in 1012.4532ms 200\n至于庞巴迪，我得到以下输出：
\nbombardier-windows-amd64.exe http://localhost:5000 -l -n 100 -t 60s\nBombarding http://localhost:5000 with 100 request(s) using 125 connection(s)\n 100 / 100 [==========================================================================================] 100.00% 11/s 8s\nDone!\nStatistics Avg Stdev Max\n Reqs/sec 11.29 99.10 1303.09\n Latency 5.78s 1.42s 8.78s\n Latency Distribution\n 50% 5.17s\n 75% 7.79s\n 90% 7.88s\n 95% 8.24s\n 99% 8.34s\n HTTP codes:\n 1xx - 0, 2xx - 100, 3xx - 0, 4xx - 0, 5xx - 0\n others - 0\n Throughput: 2.27KB/s\n以下是 Chrome 开发工具网络输出：
\n
我还使用 cURL 对其进行了测试（请注意，我必须echo [%date%, %time%]在手动执行 curl 命令后第二次应用，通过在文件中执行此操作可以提高准确性.bat\n但总体输出确认该请求花费了约 1100 毫秒：
C:\\curl\\bin>echo [%date%, %time%] && curl http://localhost:5000/\n[Sun 07/12/2020, 13:12:35.61]\nFinished in 1001 milliseconds.\nC:\\curl\\bin\\>echo [%date%, %time%]\n[Sun 07/12/2020, 13:12:37.45]\n因此，基于上述所有内容，输出似乎bombardier与其他工具报告的不同，因此我们可能会误解其输出的含义latency！我对该命令做了很少的更改，让它仅使用 10 个连接而不是默认的 125 个连接来处理 100 个请求，输出为：
bombardier-windows-amd64.exe -c10 http://localhost:5000 -l -n 100 -t 60s\nBombarding http://localhost:5000 with 100 request(s) using 10 connection(s)\n 100 / 100 [==========================================================================================] 100.00% 8/s 11s\nDone!\nStatistics Avg Stdev Max\n Reqs/sec 9.07 26.73 211.08\n Latency 1.06s 179.57ms 2.04s\n Latency Distribution\n 50% 1.01s\n 75% 1.02s\n 90% 1.07s\n 95% 1.19s\n 99% 1.86s\n HTTP codes:\n 1xx - 0, 2xx - 100, 3xx - 0, 4xx - 0, 5xx - 0\n others - 0\n Throughput: 1.79KB/s\n基于以上所述，我确认单个请求大约需要 1 秒。至于批量请求基准，请尝试Postman，否则我们需要更深入地了解bombardier延迟的确切含义及其计算方式。
更新
\n我制作了批量启动的小型控制台工具HttpClient，它确认了约 1 秒的响应时间，我还尝试了Awesome-http-benchmark中的两个基准测试工具：
baton.exe -u http://localhost:5000 -c 10 -r 100\nConfiguring to send GET requests to: http://localhost:5000\nGenerating the requests...\nFinished generating the requests\nSending the requests to the server...\nFinished sending the requests\nProcessing the results...\n\n\n====================== Results ======================\nTotal requests: 100\nTime taken to complete requests: 10.2670832s\nRequests per second: 10\n===================== Breakdown =====================\nNumber of connection errors: 0\nNumber of 1xx responses: 0\nNumber of 2xx responses: 100\nNumber of 3xx responses: 0\nNumber of 4xx responses: 0\nNumber of 5xx responses: 0\n=====================================================\n\n\ncassowary run -u http://localhost:5000 -c 10 -n 100\n\nStarting Load Test with 100 requests using 10 concurrent users\n\n 100% |\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88\xe2\x96\x88| [10s:0s] 10.2299727s\n\n\n TCP Connect.....................: Avg/mean=1.90ms Median=2.00ms p(95)=2.00ms\n Server Processing...............: Avg/mean=1014.94ms Median=1008.00ms p(95)=1093.00ms\n Content Transfer................: Avg/mean=0.17ms Median=0.00ms p(95)=1.00ms\n\nSummary:\n Total Req.......................: 100\n Failed Req......................: 0\n DNS Lookup......................: 5.00ms\n Req/s...........................: 9.78\n最后我nginx在端口 2020 上使用前面的 rev 代理来kestrel查看bombardier输出：
bombardier-windows-amd64.exe http://localhost:2020 -l -n 100 -t 60s\nBombarding http://localhost:2020 with 100 request(s) using 125 connection(s)\n 100 / 100 [==========================================================================================] 100.00% 9/s 10s\nDone!\nStatistics Avg Stdev Max\n Reqs/sec 11.76 128.07 2002.66\n Latency 9.08s 761.43ms 10.04s\n Latency Distribution\n 50% 9.06s\n 75% 9.07s\n 90% 9.07s\n 95% 10.02s\n 99% 10.04s\n HTTP codes:\n 1xx - 0, 2xx - 95, 3xx - 0, 4xx - 0, 5xx - 5\n others - 0\n Throughput: 2.51KB/s\n正如您所看到的，即使nginx它显示了 9 秒的延迟！这应该可以解决Bombarding延迟定义/计算的问题。
下面是 nginx 配置：
\nserver {\n listen 2020;\n location / {\n proxy_pass http://localhost:5000/;\n proxy_set_header Host $host;\n proxy_set_header X-Real-IP $remote_addr;\n proxy_set_header X-Forwarded-For $remote_addr;\n proxy_set_header X-Forwarded-Proto $scheme;\n proxy_http_version 1.1;\n proxy_redirect off;\n }\n奖励
\n如果你想破解 的性能，thread.sleep使其与以下类似，await Task.Delay则更改为Main：
public static void Main(string[] args)\n{\n ThreadPool.SetMinThreads(130, 130);//Don\'t Use in Production.\n CreateHostBuilder(args).Build().Run();\n}\n| 归档时间： |
|
| 查看次数： |
3099 次 |
| 最近记录： |