Testing async methods in Visual Studio 2017 with .net 4.5+ appear to block on two threads. Running the same code in .net core 2.0 does not block

Question

I had a relatively painful head-pounding issue the last few days.

While executing unit tests intended to verify async behavior in Visual Studio 2017, the async method calls appear to be blocked, but ONLY when I made calls to a web API (I promise, I had locally mocked services first, but then needed some integration tests with an API to prove the web requests behaved similarly).

I finally rang a friend to help me think this through, to which he re-wrote the same tests and showed his tests behaved as expected. The only differentiating factor was that he wrote his tests in VS2017 with .net Core 2.0.

Example Code:

    [TestMethod]
    public void TestRestSharpExecuteTaskAsync()
    {
        var tasks = new List<Task>();

        Task.WhenAll(Enumerable.Range(1, 10).Select(async s =>
        {
            // Using RestSharp, but also tested using raw WebRequests
            var restClient = new RestClient("http://google.com");
            var request = new RestRequest("/", RestSharp.Method.GET);

            Debug.WriteLine(string.Format("{0} | DEBUG: BEGIN-ExecuteTaskAsync()", DateTime.Now.ToString("MM/dd/yyyy hh:mm:ss.fff")));
            var stopwatch = new Stopwatch();
            stopwatch.Start();
            var response = await restClient.ExecuteTaskAsync(request);
            stopwatch.Stop();
            Debug.WriteLine(string.Format("{0} | DEBUG: END-ExecuteTaskAsync() completed in {1} milliseconds", DateTime.Now.ToString("MM/dd/yyyy hh:mm:ss.fff"), stopwatch.ElapsedMilliseconds));
        })).Wait();
    }

What is currently confusing me, is that when this code is executed in VS2017 with .net 4.5+ (also tested 4.6.2), the results show that there are clearly tasks waiting:

11/30/2017 10:45:45.214 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.253 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.253 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.253 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.253 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.254 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.254 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.254 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.254 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.254 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:45.368 | DEBUG: END-ExecuteTaskAsync() completed in 151 milliseconds
11/30/2017 10:45:45.368 | DEBUG: END-ExecuteTaskAsync() completed in 115 milliseconds
11/30/2017 10:45:45.414 | DEBUG: END-ExecuteTaskAsync() completed in 161 milliseconds
11/30/2017 10:45:45.420 | DEBUG: END-ExecuteTaskAsync() completed in 166 milliseconds
11/30/2017 10:45:45.466 | DEBUG: END-ExecuteTaskAsync() completed in 212 milliseconds
11/30/2017 10:45:45.473 | DEBUG: END-ExecuteTaskAsync() completed in 218 milliseconds
11/30/2017 10:45:45.520 | DEBUG: END-ExecuteTaskAsync() completed in 266 milliseconds
11/30/2017 10:45:45.522 | DEBUG: END-ExecuteTaskAsync() completed in 268 milliseconds
11/30/2017 10:45:45.570 | DEBUG: END-ExecuteTaskAsync() completed in 315 milliseconds
11/30/2017 10:45:45.578 | DEBUG: END-ExecuteTaskAsync() completed in 323 milliseconds

However, when run in the same VS2017 IDE with a .net Core 2.0 project, the tasks execute asynchronously as expected:

11/30/2017 10:45:11.922 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.976 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.976 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:11.977 | DEBUG: BEGIN-ExecuteTaskAsync()
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 230 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 176 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 175 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 175 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 175 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 176 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 176 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 175 milliseconds
11/30/2017 10:45:12.153 | DEBUG: END-ExecuteTaskAsync() completed in 176 milliseconds
11/30/2017 10:45:12.154 | DEBUG: END-ExecuteTaskAsync() completed in 177 milliseconds

Is this an IDE configuration? A bug in .net 4.x? What gives?

EDIT: The issue becomes more visible when I hit an endpoint I control the response time with:

In VS2017, .net Core 2.0:

12/01/2017 12:03:29.725 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.770 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.771 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:29.772 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4233 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4232 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4233 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4279 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4233 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4233 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4233 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4233 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4234 milliseconds
12/01/2017 12:03:34.005 | DEBUG: END-ExecuteTaskAsync() completed in 4235 milliseconds

In VS2017, .net 4.5:

12/01/2017 12:03:49.972 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.010 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:50.011 | DEBUG: BEGIN-ExecuteTaskAsync()
12/01/2017 12:03:54.132 | DEBUG: END-ExecuteTaskAsync() completed in 4158 milliseconds
12/01/2017 12:03:54.132 | DEBUG: END-ExecuteTaskAsync() completed in 4121 milliseconds
12/01/2017 12:03:58.189 | DEBUG: END-ExecuteTaskAsync() completed in 8178 milliseconds
12/01/2017 12:03:58.191 | DEBUG: END-ExecuteTaskAsync() completed in 8180 milliseconds
12/01/2017 12:04:02.236 | DEBUG: END-ExecuteTaskAsync() completed in 12225 milliseconds
12/01/2017 12:04:02.239 | DEBUG: END-ExecuteTaskAsync() completed in 12228 milliseconds
12/01/2017 12:04:06.300 | DEBUG: END-ExecuteTaskAsync() completed in 16288 milliseconds
12/01/2017 12:04:06.302 | DEBUG: END-ExecuteTaskAsync() completed in 16290 milliseconds
12/01/2017 12:04:10.362 | DEBUG: END-ExecuteTaskAsync() completed in 20350 milliseconds
12/01/2017 12:04:10.364 | DEBUG: END-ExecuteTaskAsync() completed in 20352 milliseconds

Again, the IDE is the same, the code is identical. The applied difference being the .net version.

It's late here so I may be missing something obvious, but how can you tell from the stats that you posted that there are tasks waiting? — Kenneth K., Dec 01 '17 at 04:23
Maybe it's too close to my bedtime, but I copied your two output samples to text files, compared them in BeyondCompare, and the only differences I see are in timestamps and durations, which is, of course, to be expected. I don't see what your text output has to do with any kind of "waiting" or executing "async" — Nathan, Dec 01 '17 at 04:23
@KennethK., see my edit above for test runs which show the issue more clearly. — Timothy Bock, Dec 01 '17 at 05:10
You need to remember that both `RestRequest` is not designed to be thread safe. Although I removed some of the shared properties, I am not sure that I can recommend using one instance to make parallel calls... This is work in progress. — Alexey Zimarev, Dec 06 '17 at 12:53

score 1 · Accepted Answer · answered Dec 01 '17 at 07:20

The blocking is not related to async mechanisms.

According to your logs in .NET 4.5, two requests are processed at a time. Your code in .NET 4.5+ hits the 2-connection-per-host limit effective by default in System.Net:

System.Net uses two connections per application per host by default

More info here: https://learn.microsoft.com/id-id/dotnet/framework/network-programming/best-practices-for-system-net-classes

You can change the limit as explained below. Quoting from https://social.msdn.microsoft.com/Forums/en-US/1f863f20-09f9-49a5-8eee-17a89b591007/asynchronous-httpwebrequest-maximum-connections-best-approach-threads-or-delegates?forum=netfxnetcom

Having said that you can increase the number of connections per host in the following way(s):

a) Increase the maximum for ALL hosts change the ServicePointManager.DefaultConnectionLimit

b) Increase the maximum for a specific host retrieve the ServicePoint for a host by calling ServicePointManager.FindServicePoint and then change the ServicePoint.ConnectionLimit

Note that

a) ALL these changes are only app domain wide and will not affect other processes connection limits.

b) you are contending for the network bandwith with all other applications or threads in the same application; and if you increase the connection limit too large, you may starve other(s). c) you need to experiment to find a sweet spot; for what a connection limit should be.

see also: How can I programmatically remove the 2 connection limit in WebClient

In .NET Core, this limit is not imposed by default, according to: ServicePointManager.DefaultConnectionLimit in .net core?

Felix, thanks for the lead. It looks like the missing glue (in .net 4.x) was to programmatically set the ConnectionLimit (during investigation, I did presume there was an artificial connection limit, but could not find any references as to where it needed to be set properly). After setting System.Net.ServicePointManager.DefaultConnectionLimit = X the async behavior started working as expected. — Timothy Bock, Dec 01 '17 at 15:40

Testing async methods in Visual Studio 2017 with .net 4.5+ appear to block on two threads. Running the same code in .net core 2.0 does not block

1 Answers1