Timing Request Durations Correctly

[darraghjones]

Given the following most basic of ASP.NET Core applications:

    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.");
                        }));
                });
    }

And the following appsettings.json

{
  "Logging": {
    "LogLevel": {
      "Default": "None",
      "Microsoft.AspNetCore.Hosting.Diagnostics" : "Information",
    }
  },
  "AllowedHosts": "*"
}

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

info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 1003.3658ms 200

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?

[Tratcher]

You're starving the thread pool. Change the thread sleep to an async task delay. You don't get more accurate data because the requests are stuck down at the network layer.

[davidfowl]

These metrics will need to be added in the various server implementations. I have an idea on how we can do this cheaply. We should expose a timestamp on the HttpContext that the server implementation can set that will determine the true start time of the request.

@darraghjones There are 2 things you can measure:

• Time until the response is generated
• Time until the code running on the server is over.

Which do you care about?

[darraghjones]

I guess what I care about is the worst possible experience for the end-user. So, out of those two cases, I expect the latter would be the closest to this.

[darraghjones]

Any chance these metrics will make it into dotnet 5?

[davidfowl]

.NET 5 is done so no.

[darraghjones]

i've retested the scenario, this time using the opentelemetry metrics. i can see the metric: http.server.request.duration suffers the same issue.