如何正确测量 ASP.NET Core 请求持续时间？答案

【问题标题】：How can I correctly measure ASP.NET Core request durations?如何正确测量 ASP.NET Core 请求持续时间？
【发布时间】：2020-10-24 15:36:49
【问题描述】：

鉴于以下最基本的 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 上排队的时间。

所以我的问题是如何从我的应用程序内部测量这种延迟？

【问题讨论】：

如果使用await Task.Delay(1000) 会怎样？
在这种情况下性能很好。但我并不是想提高性能。我正在尝试测量它????
你读到了吗：c-sharpcorner.com/article/…
是的，那篇文章也遇到了同样的问题。它仅在请求开始处理后启动计时器，不包括排队时间。
可能是一个糟糕的解决方案，但 new relic 非常适合为您做这样的事情。注册您的应用程序，我相信它可以监控请求所花费的时间。

标签： asp.net asp.net-core

【解决方案1】：

我在我的环境中运行了您的应用程序，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 对其进行了测试（请注意，我必须在 curl 命令后手动应用 echo [%date%, %time%] 第二次，可以通过在 .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延迟的确切含义以及它是如何计算的。

更新
我制作了一个小型控制台工具，可以批量触发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

最后我在 2020 端口上使用 nginx 作为 kestrel 前面的 rev 代理来查看 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();
}

【讨论】：

感谢您的调查。但是，在您的测试中，当您仅使用 10 个连接时，您并没有将 Web 应用置于足够的负载下，因为这会限制请求。我完全知道是什么导致了延迟......这是线程饥饿。我只想知道如何计时。这里有一个正在进行的讨论github.com/dotnet/aspnetcore/discussions/23664
并非所有测试我都使用了 10 个连接！ nginx 测试完成了默认的 125 个连接。关于线程饥饿它的明确和同意。在您的问题中，您表示请求花费了超过 1 秒的时间……好吧，我的调查表明并非如此。 nginx 情况下的额外 4 秒或 8 秒是由 Web 服务器生命周期之外的某些原因引起的。这就是 .Net 核心和操作系统中的线程管理。