如何正确衡量ASP.NET Core请求的持续时间? [英] How can I correctly measure ASP.NET Core request durations?
问题描述
给出以下最基本的ASP.NET Core应用程序(请注意Thread.Sleep):
Given the following most basic of ASP.NET Core applications (note the 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
And the following appsettings.json
{
"Logging": {
"LogLevel": {
"Default": "None",
"Microsoft.AspNetCore.Hosting.Diagnostics" : "Information",
}
},
"AllowedHosts": "*"
}
如果我进行了中等负载测试(100个请求，在我的情况下使用庞巴迪)，那么我看到的延迟约为5秒.
If I run an even moderate load test (100 requests, using bombardier in my case) I see latency of around 5 seconds.
~/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
但是，我在日志中看到的只是
However, all I see in the logs are
信息:Microsoft.AspNetCore.Hosting.Diagnostics [2]请求已完成 1003.3658ms 200
info: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished in 1003.3658ms 200
很明显，请求耗时超过1秒.我相信4秒钟是无法解释的，当请求在ThreadPool上排队时.
Clearly the requests are taking more than 1 second. I believe the unaccounted 4 seconds are when the request is queued on the ThreadPool.
所以我的问题是如何从我的应用程序内部 测量该延迟?
So my question is how can I measure this latency from inside my application?
推荐答案
我在您的环境中运行了您的应用程序，并且ASP.NET日志与您的非常相似:
I ran your application in my environment, and the ASP.NET logs very similar to yours:
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
关于庞巴迪，我得到的输出如下:
As for bombardier, I got below output:
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 Dev工具的网络输出:
And below is Chrome Dev tools network output:
我也用cURL进行了测试(请注意，我必须在curl命令之后第二次应用echo [%date%, %time%]，可以通过在.bat文件中进行操作来提高准确性)
但总体而言，输出确认该请求花费了大约1100毫秒:
Also I test it with cURL (note that I had to apply echo [%date%, %time%] second time after the curl command manually, better accuracy can be done by doing it in .bat file
but overall the output confirms that the request took ~ 1100 ms:
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个请求，并且输出为:
So based on all above, it seems that bombardier output differ than what other tools reports, hence we might misunderstood the meaning of its output latency! I made little change to the command by letting it handle the 100 requests using 10 connections only instead of default 125 connections, and the output was:
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延迟的含义以及其计算方式.
Based on all above, I confirm that the single request taking ~ 1 second. as for bulk requests benchmarks, please try Postman otherwise we need to dig deeper to understand whatbombardier Latency means exactly and how its calculated.
更新
我制作了一个小型控制台工具，可以批量触发HttpClient，它可以确认〜1秒的响应时间，此外，我还尝试了很棒的http基准测试:
Update
I made small console tool that fire HttpClient in Bulk and it confirms the ~ 1 second response time, also I tried two benchmarking tools from 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
最后，我在端口2020上使用nginx作为kestrel前面的rev代理，以查看bombardier输出:
Finally I used nginx on port 2020 as rev proxy in front of kestrel to see bombardier output:
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延迟定义/计算的问题.
As you can see, even with nginx it shows 9 seconds latency! that's should conclude an issue with Bombarding latency definition/calcs.
以下是Nginx配置:
Below is nginx config:
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更改为:
Bonus
If you want to hack the performance of thread.sleep to be similar as await Task.Delay then change Main to:
public static void Main(string[] args)
{
ThreadPool.SetMinThreads(130, 130);//Don't Use in Production.
CreateHostBuilder(args).Build().Run();
}
这篇关于如何正确衡量ASP.NET Core请求的持续时间?的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
