Strange behavior of starting multiple tasks that block

Question

Here is a test method that starts (without awaiting) 100 Tasks that each call GetConsumingEnumerable on a BlockingCollection. (Update: the behavior described below is not specific to this method; it could be any synchronously blocking method call.) I would like to understand why after the first 10 tasks have started in parallel, the subsequent tasks start sequentially, each waiting almost exactly 1000 ms before the next task:

[TestMethod]
public void Test()
{
    BlockingCollection<int> list = new();
    Console.WriteLine(DateTime.UtcNow + @": " + "START");

    for (int i = 0; i < 100; i++)
    {
        int x = i;
        Task.Run(() =>
        {
            Console.WriteLine($"{DateTime.UtcNow}: Starting {x}");

            // This will just block
            foreach (int item in list.GetConsumingEnumerable())
            {
                Console.WriteLine($"{DateTime.UtcNow}: foo {x}");
            }

            // We'll never get here:
            Console.WriteLine($"{DateTime.UtcNow}: Finishing {x}");
        });
    }
    Console.WriteLine(DateTime.UtcNow + @": " + "END");
    // Just to give the test enough time to print all messages
    Thread.Sleep(100_000);
}

Here are the first 26 lines of the output:

02.02.2021 12:17:41: START
02.02.2021 12:17:41: END
02.02.2021 12:17:41: Starting 9
02.02.2021 12:17:41: Starting 0
02.02.2021 12:17:41: Starting 1
02.02.2021 12:17:41: Starting 6
02.02.2021 12:17:41: Starting 4
02.02.2021 12:17:41: Starting 2
02.02.2021 12:17:41: Starting 5
02.02.2021 12:17:41: Starting 7
02.02.2021 12:17:41: Starting 3
02.02.2021 12:17:41: Starting 8
02.02.2021 12:17:41: Starting 10
02.02.2021 12:17:42: Starting 11
02.02.2021 12:17:43: Starting 12
02.02.2021 12:17:44: Starting 13
02.02.2021 12:17:45: Starting 14
02.02.2021 12:17:45: Starting 15
02.02.2021 12:17:46: Starting 16
02.02.2021 12:17:47: Starting 17
02.02.2021 12:17:48: Starting 18
02.02.2021 12:17:49: Starting 19
02.02.2021 12:17:50: Starting 20
02.02.2021 12:17:51: Starting 21
02.02.2021 12:17:52: Starting 22
02.02.2021 12:17:53: Starting 23
02.02.2021 12:17:54: Starting 24

The first few lines are as expected. But why does it start waiting 1000 ms after task #10? My first assumption was that since GetConsumingEnumerable blocks the thread, perhaps the threads in the thread pool are all used up after the 10th task, but that doesn't explain the 1000 ms delay.

Answer 1

[Thanks to Jon Skeet's and Theodor Zoulias' comments]

Since GetConsumingEnumerable blocks the thread, after the 10th task has run, all available idle threads in the thread pool are blocked. This has nothing to do with GetConsumingEnumerable specifically: the same behavior occurs whenever the task blocks (e.g. replacing the call by Thread.Sleep(Timeout.Infinite)).

As explained in the thread pool documentation, expanding the thread pool is delayed:

As part of its thread management strategy, the thread pool delays before creating threads. Therefore, when a number of tasks are queued in a short period of time, there can be a significant delay before all the tasks are started.

To confirm this behavior, one could increase the minimum number of on-demand threads using

ThreadPool.SetMinThreads(1000, 1000);

With this setting, all 100 tasks run without delay.