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.3658 毫秒内完成 200
显然，请求花费的时间超过 1 秒。我相信未计入的 4 秒是请求在 ThreadPool 上排队的时间。
所以我的问题是如何从我的应用程序内部测量这种延迟？
解决方案
我在我的环境中运行了您的应用程序，并且 ASP.NET 日志与您的非常相似：
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1022.4689ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1004.1694ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1003.4582ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1004.3703ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1003.3915ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1004.3106ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1003.122ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1017.028ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1004.2742ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1006.5832ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1004.9214ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5000/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1012.4532ms 200
至于bombardier，我得到以下输出：
bombardier-windows-amd64.exe http://localhost:5000 -l -n 100 -t 60s
Bombarding http://localhost:5000 with 100 request(s) using 125 connection(s)
100 / 100 [==========================================================================================] 100.00% 11/s 8s
Done!
Statistics Avg Stdev Max
Reqs/sec 11.29 99.10 1303.09
Latency 5.78s 1.42s 8.78s
Latency Distribution
50% 5.17s
75% 7.79s
90% 7.88s
95% 8.24s
99% 8.34s
HTTP codes:
1xx - 0, 2xx - 100, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 2.27KB/s
以下是 Chrome 开发工具网络输出：
我还使用 cURL 对其进行了测试（请注意，我必须echo [%date%, %time%]在 curl 命令之后手动应用第二次，可以通过在.bat文件中执行此操作来提高准确性，但总体而言，输出确认请求花费了约 1100 毫秒：
C:\curl\bin>echo [%date%, %time%] && curl http://localhost:5000/
[Sun 07/12/2020, 13:12:35.61]
Finished in 1001 milliseconds.
C:\curl\bin\>echo [%date%, %time%]
[Sun 07/12/2020, 13:12:37.45]
因此，基于以上所有，bombardier输出似乎与其他工具报告的不同，因此我们可能误解了其输出的含义latency！我通过让它仅使用 10 个连接而不是默认的 125 个连接来处理 100 个请求，对命令进行了少许更改，输出为：
bombardier-windows-amd64.exe -c10 http://localhost:5000 -l -n 100 -t 60s
Bombarding http://localhost:5000 with 100 request(s) using 10 connection(s)
100 / 100 [==========================================================================================] 100.00% 8/s 11s
Done!
Statistics Avg Stdev Max
Reqs/sec 9.07 26.73 211.08
Latency 1.06s 179.57ms 2.04s
Latency Distribution
50% 1.01s
75% 1.02s
90% 1.07s
95% 1.19s
99% 1.86s
HTTP codes:
1xx - 0, 2xx - 100, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 1.79KB/s
基于以上所有，我确认单个请求大约需要 1 秒。至于批量请求基准，请尝试，Postman否则我们需要更深入地了解bombardier延迟的确切含义以及它的计算方式。
更新
我制作了在 Bulk 中触发的小型控制台工具，HttpClient它确认了 ~ 1 秒的响应时间，我还尝试了awesome-http-benchmark 的两个基准测试工具：
baton.exe -u http://localhost:5000 -c 10 -r 100
Configuring to send GET requests to: http://localhost:5000
Generating the requests...
Finished generating the requests
Sending the requests to the server...
Finished sending the requests
Processing the results...
====================== Results ======================
Total requests: 100
Time taken to complete requests: 10.2670832s
Requests per second: 10
===================== Breakdown =====================
Number of connection errors: 0
Number of 1xx responses: 0
Number of 2xx responses: 100
Number of 3xx responses: 0
Number of 4xx responses: 0
Number of 5xx responses: 0
=====================================================
cassowary run -u http://localhost:5000 -c 10 -n 100
Starting Load Test with 100 requests using 10 concurrent users
100% |████████████████████████████████████████| [10s:0s] 10.2299727s
TCP Connect.....................: Avg/mean=1.90ms Median=2.00ms p(95)=2.00ms
Server Processing...............: Avg/mean=1014.94ms Median=1008.00ms p(95)=1093.00ms
Content Transfer................: Avg/mean=0.17ms Median=0.00ms p(95)=1.00ms
Summary:
Total Req.......................: 100
Failed Req......................: 0
DNS Lookup......................: 5.00ms
Req/s...........................: 9.78
最后，我nginx在端口 2020 上用作 rev 代理，kestrel以查看bombardier输出：
bombardier-windows-amd64.exe http://localhost:2020 -l -n 100 -t 60s
Bombarding http://localhost:2020 with 100 request(s) using 125 connection(s)
100 / 100 [==========================================================================================] 100.00% 9/s 10s
Done!
Statistics Avg Stdev Max
Reqs/sec 11.76 128.07 2002.66
Latency 9.08s 761.43ms 10.04s
Latency Distribution
50% 9.06s
75% 9.07s
90% 9.07s
95% 10.02s
99% 10.04s
HTTP codes:
1xx - 0, 2xx - 95, 3xx - 0, 4xx - 0, 5xx - 5
others - 0
Throughput: 2.51KB/s
如您所见，即使nginx它显示 9 秒延迟！这应该结束Bombarding延迟定义/计算的问题。
下面是 nginx 配置：
server {
listen 2020;
location / {
proxy_pass http://localhost:5000/;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $remote_addr;
proxy_set_header X-Forwarded-Proto $scheme;
proxy_http_version 1.1;
proxy_redirect off;
}
奖金
如果你想破解thread.sleep类似于await Task.Delay然后更改Main为：
public static void Main(string[] args)
{
ThreadPool.SetMinThreads(130, 130);//Don't Use in Production.
CreateHostBuilder(args).Build().Run();
}
推荐阅读
- python - 对于相同大小的列表，为什么深拷贝比浅拷贝慢得多？
- bigcommerce - 有没有办法使用 /products/${productId}/variants 端点创建带有选项的产品变体？
- javascript - 反应：调用“componentDidMount”时 this.reference.current 为空
- php - php数组到变量
- c++ - 创建类引用本身的智能指针成员是c ++中的优雅设计模式吗？
- c# - 如何添加和修改速度变量？
- ruby-on-rails - 使用 PostgreSQL 按日期时间排序嵌套对象
- r - 绘制离散事件的时间线
- angular - angular 7 cli 在自己的目录中生成每个服务、管道等
- autodesk-forge - 为什么 v2 Design Automation API 的 DELETE WorkItems 端点显然不存在？