What makes mixing of sync and async Tasks so terrible slow in the following example?

Question

I ran into big problems when (unintentionally) mixing async with syn tasks: The following examples are compressed versions of the original problem.

Platform is Windows 10, Microsoft.NET.Sdk.Web, 2 Cores, 4 Logical prcessors @ 2.4 GHz

This code represents the original problem: it executes one sync and one async tasks each 20 times:

var sema = new SemaphoreSlim(1);

var tasks = new List<Task>();

for (int i = 0; i < 20; i++)
{
    var t2 = Task.Run(async () =>
    {
        var sw = new Stopwatch();
        sw.Start();
        await sema.WaitAsync().ConfigureAwait(false);
        try
        {
            await Task.Delay(1).ConfigureAwait(false);
        }
        finally
        {
            sema.Release();
        }
        sw.Stop();
        Console.WriteLine($"sync {sw.Elapsed}");
    });

    var t1 = Task.Run(() =>
    {
        var sw = new Stopwatch();
        sw.Start();
        sema.Wait();
        try
        {
        }
        finally
        {
            sema.Release();
        }
        sw.Stop();
        Console.WriteLine($"async {sw.Elapsed}");
    });

    tasks.Add(t1);
    tasks.Add(t2);
}

await Task.WhenAll(tasks).ConfigureAwait(false);

It takes about 16s to complete. Notably the first sync is after 800ms.

sync 00:00:00.8306484
sync 00:00:16.8401071
sync 00:00:16.8559379
sync 00:00:16.8697014
async 00:00:16.8697706
async 00:00:16.8699273
async 00:00:16.8710140
async 00:00:16.8710523
sync 00:00:16.0248058
async 00:00:16.0246810
sync 00:00:15.0783237
async 00:00:15.0782280
sync 00:00:14.5762648
async 00:00:14.5760971
sync 00:00:13.5689368
async 00:00:13.5591823
sync 00:00:12.6271075
async 00:00:12.6270483
sync 00:00:11.6318846
async 00:00:11.6317560
sync 00:00:10.6406636
async 00:00:10.6404542
sync 00:00:09.1580280
async 00:00:09.1574764
sync 00:00:08.1862783
async 00:00:08.1860869
sync 00:00:07.2034033
async 00:00:07.2032430
sync 00:00:06.2139071
async 00:00:06.2136905
sync 00:00:05.2354887
async 00:00:05.2353404
sync 00:00:04.2503136
async 00:00:04.2501821
sync 00:00:03.2656311
async 00:00:03.2655521
sync 00:00:02.2806897
async 00:00:02.2805796
sync 00:00:01.2974060
async 00:00:01.2972398

In contrast, the following code runs two async tasks each 20 times:

var sema = new SemaphoreSlim(1);

var tasks = new List<Task>();

for (int i = 0; i < 20; i++)
{
    var t2 = Task.Run(async () =>
    {
        var sw = new Stopwatch();
        sw.Start();
        await sema.WaitAsync().ConfigureAwait(false);
        try
        {
            await Task.Delay(1).ConfigureAwait(false);
        }
        finally
        {
            sema.Release();
        }
        sw.Stop();
        Console.WriteLine($"sync {sw.Elapsed}");
    });

    var t1 = Task.Run(async () =>
    {
        var sw = new Stopwatch();
        sw.Start();
        await sema.WaitAsync().ConfigureAwait(false);
        try
        {
        }
        finally
        {
            sema.Release();
        }
        sw.Stop();
        Console.WriteLine($"async {sw.Elapsed}");
    });

    tasks.Add(t1);
    tasks.Add(t2);
}

await Task.WhenAll(tasks).ConfigureAwait(false);

It takes only 300ms to complete:

async 00:00:00.0180861
sync 00:00:00.0329542
async 00:00:00.0181292
sync 00:00:00.0177771
async 00:00:00.0432851
sync 00:00:00.0476872
sync 00:00:00.0635321
sync 00:00:00.0774490
async 00:00:00.0775557
async 00:00:00.0775724
async 00:00:00.0775398
sync 00:00:00.0942652
sync 00:00:00.1082544
async 00:00:00.1080930
sync 00:00:00.1240859
async 00:00:00.1246952
sync 00:00:00.1397922
async 00:00:00.1414005
sync 00:00:00.1547058
async 00:00:00.1546395
sync 00:00:00.1705435
async 00:00:00.1705003
sync 00:00:00.1863422
async 00:00:00.1865136
sync 00:00:00.2052246
async 00:00:00.2054538
sync 00:00:00.2172049
async 00:00:00.2171460
sync 00:00:00.2330110
async 00:00:00.2329556
sync 00:00:00.2489691
async 00:00:00.2492344
sync 00:00:00.2647401
async 00:00:00.2645481
async 00:00:00.2645736
sync 00:00:00.2785660
async 00:00:00.2785652
sync 00:00:00.2944074
sync 00:00:00.3116578
async 00:00:00.3184570

I know, that mixing async and sync should be avoided. But what is the reason for the immense delay in the first variant? I cannot imagine what goes on within the 16 seconds, which is almost "infinite time" for the CPU.

Moreover, why is even the first message of the first case only after 800ms: This time itself is already very unexpected.

Answer 1

The thread pool is designed for operations that run quickly. Your first program schedules a bunch of work to the thread pool that runs for an extremely long period of time (because you've scheduled a ton of operations that can only ever run sequentially anyway, so they're all waiting on each other), you're scheduling more work than there are workers, so you end up in the situation where every single worker is just sitting there waiting on other work further down the queue of the thread pool. In this situation you've basically generated the most common async deadlock situation as you're blocking the scheduler from running the continuations needed to let work finish, only it doesn't technically deadlock because the thread pool will notice that no work is being done, and add more workers over time, each of which will just sit there and do nothing, waiting for things further down the queue of work to finally be scheduled. Eventually you end up having enough thread pool threads that work can actually proceed. But work won't proceed until the thread pool finally has created about as many threads as you have work scheduled for it, and as you can see, that takes some time.

When you do the whole thing asynchronously you don't have that common sync over async problem of blocking the scheduler from doing more work, as the work you're having the thread pool do is only ever the actual work that needs to be done, instead of having the workers sit there and block while waiting for other things to finish.