aspnetcore: Slow response when sending concurrent requests from the same connection

I have a web API server that implements by ASP.NET core 2.0.

I have a web page that implements by Angular5. The page calls two different API concurrently. Each API response time about 300ms, but If I call API one by one, each response about 20ms. It seems like the request are locked by something?

To verify this issue, I create a Web API project by using default Visual Studio 2017 template.

    [Route("api/[controller]")]
    public class ValuesController : Controller
    {
        // GET api/values
        [HttpGet]
        public IEnumerable<string> Get()
        {
            return new string[] { "value1", "value2" };
        }
  }

And a console program that calls API by HttpClient.

        public static HttpClient _http = new HttpClient();

        static async Task<HttpResponseMessage> HttpGet(string uri)
        {
            var watch = new Stopwatch();
            watch.Start();

            var response = await _http.GetAsync(uri);

            watch.Stop();
            Console.WriteLine("time = " + watch.ElapsedMilliseconds);

            return response;
        }

        static void TestWebApi()
        {
            // call first time to initial the httpClient
            var x = HttpGet("http://localhost:52876/api/values").Result;

            Console.WriteLine("Sync....");
            for (var i = 0; i < 5; i++)
            {
                var r = HttpGet("http://localhost:52876/api/values").Result;
                var j = r.Content.ReadAsStringAsync().Result;
            }

            Console.WriteLine("Async....");
            for (var i = 0; i < 5; i++)
            {
                Task.Run(() =>
                {
                    var id = Guid.NewGuid();
                    Console.WriteLine($"[{id}] send...");
                    var r = HttpGet("http://localhost:52876/api/values").Result;
                    var j = r.Content.ReadAsStringAsync().Result;
                    Console.WriteLine($"[{id}] got response");
                });
            }
        }

        static void Main(string[] args)
        {
            TestWebApi();

            Console.ReadLine();
        }

Output:

time = 314
Sync....
time = 38
time = 16
time = 97
time = 16
time = 16
Async....
[382a2624-520c-4ee2-b652-9a22f623263d] send...
[41b61a01-046d-4679-b71b-86976d5ac190] send...
[e2c32f5d-2e16-4e96-a337-a3d8d4dcca6e] send...
[227beb1d-3732-4b73-8cfa-99ab883689a3] send...
[78400e4c-841b-4c83-9936-a13d9acad8bc] send...
time = 298
[227beb1d-3732-4b73-8cfa-99ab883689a3] got response
time = 334
[e2c32f5d-2e16-4e96-a337-a3d8d4dcca6e] got response
time = 358
[78400e4c-841b-4c83-9936-a13d9acad8bc] got response
time = 461
[382a2624-520c-4ee2-b652-9a22f623263d] got response
time = 488
[41b61a01-046d-4679-b71b-86976d5ac190] got response

The result matches my production website. The response time of the concurrent request is slow.

P.S I got the same result if I run web API on the IIS server 8.5

About this issue

Original URL
State: closed
Created 6 years ago
Comments: 15 (3 by maintainers)

Most upvoted comments

The whole problem has nothing to do with IIS, Kestrel, Debug/Release Mode or Visual Studio, it’s just bad async code and bad measurement.

See this altered code:

        public static HttpClient _http = new HttpClient();

        static async Task<HttpResponseMessage> HttpGet(string uri)
        {
            var watch = new Stopwatch();
            watch.Start();

            var response = await _http.GetAsync(uri);

            watch.Stop();
            Console.WriteLine("time = " + watch.ElapsedMilliseconds);

            return response;
        }

        static void TestWebApi()
        {
            // call first time to initial the httpClient
            var x = HttpGet("http://example.com/").Result;

            Console.WriteLine("Sync....");
            Stopwatch totalTime = Stopwatch.StartNew();
            for (var i = 0; i < 5; i++)
            {
                var r = HttpGet("http://example.com/").Result;
                var j = r.Content.ReadAsStringAsync().Result;
            }
            totalTime.Stop();
            Console.WriteLine("totalTime (sync): " + totalTime.Elapsed.TotalSeconds.ToString("f2") + " s");

            Console.WriteLine("Async....");
            var pendingTasks = new List<Task>();
            totalTime.Restart();
            for (var i = 0; i < 5; i++)
            {
                var t = Task.Run(async () =>
                {
                    // var id = Guid.NewGuid();
                    // Console.WriteLine($"[{id}] send...");
                    using (var r = await HttpGet("http://example.com/"))
                    {
                        var j = await r.Content.ReadAsStringAsync();
                        Console.WriteLine("Loaded: " + j.Substring(0, Math.Min(30, j.Length)).Replace('\n', ' ').Replace('\r', ' ') + " ...");
                    }
                    // Console.WriteLine($"[{id}] got response");
                });
                pendingTasks.Add(t);
            }
            Task.WaitAll(pendingTasks.ToArray());
            Console.WriteLine("totalTime (async): " + totalTime.Elapsed.TotalSeconds.ToString("f2") + " s");
        }

        static void Main(string[] args)
        {
            TestWebApi();

            Console.ReadKey();
        }

Output:

time = 677
Sync....
time = 209
time = 189
time = 206
time = 203
time = 164
totalTime (sync): 0,98 s
Async....
time = 266
Loaded: <!doctype html> <html> <head>  ...
time = 438
Loaded: <!doctype html> <html> <head>  ...
time = 439
Loaded: <!doctype html> <html> <head>  ...
time = 442
Loaded: <!doctype html> <html> <head>  ...
time = 440
Loaded: <!doctype html> <html> <head>  ...
totalTime (async): 0,46 s

As you can see, the async method needs 460 ms totalTime, the sync approach 980 ms totalTime.

The difference is, that my code version run in parallel while yours run in different tasks but only synchronous.

So sync mode is just the sum of timings: 209 + 189 + 206 + 203 + 164 = 971 ms = totalTime

But in real async it is the longest call: 440 ms ~ totalTime

samsosa on Mar 28, 2018