Synchronous Web Api and response time depending on the thread and request count

Question

I'm messing with sync/async to learn them better and encountered one thing that I can't explain. I've set up Web Api project with two endpoints which read data from the db. One is sync another one is async. Both do the same operation that takes ~5s on the database side (intentionally throttled). Also I throttled web server in terms of threads:

ThreadPool.SetMinThreads(2, 2);
ThreadPool.SetMaxThreads(2, 2);

Currenyly I'm worried by synchronous method behaviour, async works as I expect it to work.

When I send 3 requests to synchronous endpoint simultaneously, I end up with 2 responses in 5 seconds, and 1 response in 10 seconds, which seems logical to me:

However, when I send 4 requests to synchronous endpoint simultaneously, I end up with 4 responses which all take 10 seconds (but I expect 2 to be 5s and other 2 to be 10s)

In web server logs i see that these 4 requests in fact processed synchronously and response times are ~5s:

 

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:57128/test/syncDb  
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:57128/test/syncDb  
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "GetSyncDb", controller = "Test"}. Executing controller action with signature System.String GetSyncDb() on controller WebApiAsyncAwait.Controllers.TestController (WebApiAsyncAwait).
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "GetSyncDb", controller = "Test"}. Executing controller action with signature System.String GetSyncDb() on controller WebApiAsyncAwait.Controllers.TestController (WebApiAsyncAwait).
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait) in 5008.3885ms
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait) in 5010.472000000001ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 5026.9979ms 200 text/plain; charset=utf-8
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 5032.421200000001ms 200 text/plain; charset=utf-8
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:57128/test/syncDb  
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:57128/test/syncDb  
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "GetSyncDb", controller = "Test"}. Executing controller action with signature System.String GetSyncDb() on controller WebApiAsyncAwait.Controllers.TestController (WebApiAsyncAwait).
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "GetSyncDb", controller = "Test"}. Executing controller action with signature System.String GetSyncDb() on controller WebApiAsyncAwait.Controllers.TestController (WebApiAsyncAwait).
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait) in 5007.105500000001ms
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait) in 5005.6482000000005ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'WebApiAsyncAwait.Controllers.TestController.GetSyncDb (WebApiAsyncAwait)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 5021.8341ms 200 text/plain; charset=utf-8
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 5023.8319ms 200 text/plain; charset=utf-8

 

Endpoint code:

[HttpGet]
[Route("syncDb")]
public string GetSyncDb()
{
    string connStr = @"Server=localhost\SQLEXPRESS;Database=AdventureWorks;Trusted_Connection=True;";
    using (SqlConnection conn = new SqlConnection(connStr))
    {
        conn.Open();
        using (SqlCommand cmd = conn.CreateCommand())
        {
            cmd.CommandText = @"SELECT TOP (1) * FROM [AdventureWorks].[Sales].[CreditCard] WAITFOR DELAY '00:00:05'";

            using (SqlDataReader reader = cmd.ExecuteReader())
            {
                var res = reader.Read();
                return "Ok";
            }
        }
    }
}

I'm using Fiddler to send requests. Is it something with Fiddler (because logs are ok), or I'm missing something in the understanding of how this works?

Answer 1

In ASP .NET Core there is a lot of async stuff executed behind the scene. In particular, before your controller action is executed, a thread must read and parse HTTP request sent by fiddler. After the action execution, another thread (maybe the same) is needed to write a response back to the fiddler.

So what happened in your first case with 3 requests:

1. As you allow max 2 threads, two actions were started simultaneously and were blocked immediately by sync call reader.Read().
2. After ~5s, both threads completed the action GetSyncDb(), but the response has not yet been sent.
3. Now 2 threads are free, one can handle the 3rd request (and be blocked for ~5s) and the other can be used by ASP to write responses to the client.

Thus, 2 requests end after ~5s while the third after ~10s.

in the case of 4 requests:

1. Two actions were started simultaneously and were blocked immediately by sync call reader.Read().
2. After ~5s, both threads completed the action GetSyncDb(), but the response has not yet been sent.
3. The other 2 requests were started and block all available threads. ASP doesn't have any worker thread available. But it needs them to write response and complete the the first 2 requests.
4. After next ~5s, both threads are released and ASP can finally write all responses.

Therefore all requests end after ~10s. But of course it is random. Sometimes ASP can catch the free thread and complete first responses before they are blocked by the other requests.