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.

I *suspect* you're seeing the thread pool expanding at the rate of 1 thread per second. Have you tried removing the BlockingCollection part from the example, and just starting 100 tasks which do nothing but log their index and then block (e.g. with Thread.Sleep)? — Jon Skeet, Feb 02 '21 at 12:33
You could try adding this statement at the start of your program: `ThreadPool.SetMinThreads(1000, 1000);`, and see if it makes any difference. — Theodor Zoulias, Feb 02 '21 at 12:53
@JonSkeet Sure, that is why I know it's got to do with the `BlockingCollection`. The thread pool expansion sounds plausible, but is the rate of 1/s a known fact or is there a reason for that? — Mo B., Feb 02 '21 at 12:56
@TheodorZoulias Yes, you are right, that removed the delay. Which also confirms Jon Skeet's hypothesis of the rate-restricted thread pool expansion. — Mo B., Feb 02 '21 at 12:59
AFAIK the rate that the `ThreadPool` injects now threads when being saturated is one thread every 500 msec. You could get more detailed information by including the milliseconds to the measurements: `{DateTime.UtcNow:HH:mm:ss.fff}`. — Theodor Zoulias, Feb 02 '21 at 13:21
@MoB.: When you say "Sure, that is why I know it's got to do with the `BlockingCollection`" I'm not sure what you mean - if you get the same result with `Thread.Sleep`, it's really *not* anything to do with `BlockingCollection`, it's just "the thread being blocked for whatever reason", isn't it? — Jon Skeet, Feb 02 '21 at 14:06
@JonSkeet Sorry, my comment was misleading. You are right: whenever the tasks are blocking we get this behavior - it could also be `Thread.Sleep`. — Mo B., Feb 02 '21 at 14:47
Right. You could *consider* editing your post accordingly, as we now know it's really "Strange behavior of the threadpool when threads are blocked". — Jon Skeet, Feb 02 '21 at 14:53

Mo B. · Accepted Answer · 2021-02-02T14:50:05.760

[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.

Strange behavior of starting multiple tasks that block

1 Answers1