Parallel.For with long running tasks blocks background Timers on NET 6.0

[snakefoot]

Description

When starting Parallel.For with more long running tasks than CPU-cores, then suddenly background-timers no longer fires on .NET 6.0. Instead the Parallel.For continues to schedule new threads.

Configuration

When running this snippet on .NET 6.0, then background-Timer stops writing to console.

using System;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using NLogWait;

Console.Title = $"LogDemo - {Environment.ProcessId} (PID)";

var builder = Host.CreateDefaultBuilder(args);

var host = builder
           .ConfigureServices(services =>
           {
               services.AddLogging(builder => builder.AddConsole());
               services.AddHostedService<Worker>();
           })
           .Build();
await host.RunAsync();

namespace NLogWait
{
    public sealed class Worker : BackgroundService
    {
        private readonly ILogger<Worker> _logger;

        public Worker(ILogger<Worker> logger) => _logger = logger;

        private readonly object SyncRoot = new object();
        private Timer Timer;
        private readonly System.Collections.Concurrent.ConcurrentQueue<int> Queue = new System.Collections.Concurrent.ConcurrentQueue<int>();

        protected override Task ExecuteAsync(CancellationToken stoppingToken)
        {
            Timer = new Timer((s) => TimerExecute());
            _logger.LogInformation("Timer Started");
            Timer.Change(0, Timeout.Infinite);

            Parallel.For(0,
                          200,
                          new ParallelOptions(), // { MaxDegreeOfParallelism = System.Environment.ProcessorCount * 2 },
                          _ =>
                          {
                              _logger.LogInformation("Worker Thead Created");
                              while (!stoppingToken.IsCancellationRequested)
                              {
                                  while (Queue.Count > 1000)
                                  {
                                      lock (SyncRoot)
                                      {
                                          if (Queue.Count < 1000)
                                              break;
                                          Monitor.Wait(SyncRoot);
                                      }
                                  }
                                  Queue.Enqueue(System.Environment.CurrentManagedThreadId);
                              }
                          });

            return Task.CompletedTask;
        }

        private void TimerExecute()
        {
            do
            {
                _logger.LogInformation("Timer Working");

                lock (SyncRoot)
                {
                    for (int i = 0; i < 1000; ++i)
                    {
                        if (!Queue.TryDequeue(out var _))
                            break;
                    }
                    Monitor.PulseAll(SyncRoot);
                }
            } while (Queue.Count > 1000);

            _logger.LogInformation("Timer Scheduled");
            Timer.Change(1, Timeout.Infinite);
        }
    }
}

Regression?

When running on .NET 5.0, then background-timer still get time-slots.

Analysis

The issue disappear when using:

new ParallelOptions() { MaxDegreeOfParallelism = System.Environment.ProcessorCount * 2 },

[ghost]

Tagging subscribers to this area: @mangod9
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

When starting Parallel.For with more long running tasks than CPU-cores, then suddenly background-timers no longer fires on .NET 6.0. Instead the Parallel.For continues to schedule new threads.

Configuration

When running this snippet on .NET 6.0, then Timer stops writing to console.

using System;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using NLogWait;

Console.Title = $"LogDemo - {Environment.ProcessId} (PID)";

var builder = Host.CreateDefaultBuilder(args);

var host = builder
           .ConfigureServices(services =>
           {
               services.AddLogging(builder => builder.AddConsole());
               services.AddHostedService<Worker>();
           })
           .Build();
await host.RunAsync();

namespace NLogWait
{
    public sealed class Worker : BackgroundService
    {
        private readonly ILogger<Worker> _logger;

        public Worker(ILogger<Worker> logger) => _logger = logger;

        private readonly object SyncRoot = new object();
        private Timer Timer;
        private readonly System.Collections.Concurrent.ConcurrentQueue<int> Queue = new System.Collections.Concurrent.ConcurrentQueue<int>();

        protected override Task ExecuteAsync(CancellationToken stoppingToken)
        {
            Timer = new Timer((s) => TimerExecute());
            _logger.LogInformation("Timer Started");
            Timer.Change(0, Timeout.Infinite);

            Parallel.For(0,
                          100,
                          new ParallelOptions(), // { MaxDegreeOfParallelism = System.Environment.ProcessorCount * 2 },
                          _ =>
                          {
                              while (!stoppingToken.IsCancellationRequested)
                              {
                                  while (Queue.Count > 1000)
                                  {
                                      lock (SyncRoot)
                                      {
                                          if (Queue.Count < 1000)
                                              break;
                                          Monitor.Wait(SyncRoot);
                                      }
                                  }
                                  Queue.Enqueue(System.Environment.CurrentManagedThreadId);
                              }
                          });

            return Task.CompletedTask;
        }

        private void TimerExecute()
        {
            do
            {
                _logger.LogInformation("Timer Working");

                lock (SyncRoot)
                {
                    for (int i = 0; i < 1000; ++i)
                    {
                        if (!Queue.TryDequeue(out var _))
                            break;
                    }
                    Monitor.PulseAll(SyncRoot);
                }
            } while (Queue.Count > 1000);

            _logger.LogInformation("Timer Scheduled");
            Timer.Change(1, Timeout.Infinite);
        }
    }
}

Regression?

It is working on .NET 5.0, where background-timer still get priority.

Analysis

The issue disappear when using:

new ParallelOptions() { MaxDegreeOfParallelism = System.Environment.ProcessorCount * 2 },

Author:	snakefoot
Assignees:	-
Labels:	area-System.Threading, tenet-performance, untriaged
Milestone:	-

[DaveSenn]

i did some testing. It looks like the timer callback will not be invoked until the thread pool has grown big enough to provide the number of threads required by parallel.for + 1 (for the timer).

The timer will fire from the start when the thread pool min thread count is set manually.

var t = new Timer( _ => Console.Write( "." ), null, 100, 100 );

//ThreadPool.SetMinThreads( Environment.ProcessorCount * 2, Environment.ProcessorCount * 2 );
var wait = new ManualResetEvent( false );
Parallel.For( 0,
              100,
              new() { MaxDegreeOfParallelism = Environment.ProcessorCount * 2 },
              _ =>
              {
                  Console.Write( $"Start {ThreadPool.ThreadCount}" );
                  wait.WaitOne();
              } );

Console.ReadLine();

[stephentoub]

@kouvel, this looks like a problem with the portable thread pool. The native timer callback appears to be coming in via an UnmanagedThreadPoolWorkItem into the "time-sensitive" queue. What I don't understand here is the "time-sensitive" queue is deprioritized and only queried if there's no work in either the global or per-thread queues:

runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs

Lines 550 to 554 in d9afc1e

	// No work in the normal queues, check for time-sensitive work items
	if (ThreadPool.SupportsTimeSensitiveWorkItems)
	{
	callback = TryDequeueTimeSensitiveWorkItem();
	}

Why? That seems backwards, and would also fully explain the issue seen here: as long as there's some work in one of the regular queues, timers won't fire.

[kouvel]

There appears to be a slight difference from before. Since all thread pool threads are blocked, when a new thread is added, in .NET 5 it used to alternate between the unmanaged and managed queues as a starting point. So every two threads that are added due to starvation it would check the unmanaged queue and find timer callbacks to run. With the portable thread pool, the managed queues are checked first and the time-sensitive queue (analogous to the unmanaged queue) is checked periodically. However, since every work item in the managed queues takes over the thread forever, the timers don't get a chance to run. This is usually not an issue since thread pool work items are typically short (or at least ideally). It should be possible to change it to something similar (or to just check the time-sensitive queue first) when starting to dispatch work.

What I don't understand here is the "time-sensitive" queue is deprioritized and only queried if there's no work in either the global or per-thread queues:

The time-sensitive queue is also checked periodically (every quantum) here:

runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs

Lines 725 to 754 in c159108

	// Check if the dispatch quantum has expired
	if ((uint)(currentTickCount - startTickCount) < DispatchQuantumMs)
	{
	continue;
	}
	// The quantum expired, do any necessary periodic activities
	#pragma warning disable CS0162 // Unreachable code detected. SupportsTimeSensitiveWorkItems may be a constant in some runtimes.
	if (!ThreadPool.SupportsTimeSensitiveWorkItems)
	{
	// The runtime-specific thread pool implementation does not support managed time-sensitive work, need to
	// return to the VM to let it perform its own time-sensitive work. Tell the VM we're returning normally.
	// Ensure a thread is requested before returning.
	returnValue = true;
	break;
	}
	// This method will continue to dispatch work items. Refresh the start tick count for the next dispatch
	// quantum and do some periodic activities.
	startTickCount = currentTickCount;
	// Periodically refresh whether logging is enabled
	workQueue.RefreshLoggingEnabled();
	// Consistent with CoreCLR currently, only one time-sensitive work item is run periodically between quantums
	// of time spent running work items in the normal thread pool queues, until the normal queues are depleted.
	// These are basically lower-priority but time-sensitive work items.
	workItem = workQueue.TryDequeueTimeSensitiveWorkItem();
	#pragma warning restore CS0162

It emulates what the native thread pool did, except that the native thread pool was also alternating between managed/unmanaged queues when starting to dispatch work.

[stephentoub]

Thanks, @kouvel.

This is usually not an issue since thread pool work items are typically short (or at least ideally).

Yeah, I agree the ideal is that work items are shorter; unfortunately, things don't always work out that way.

It should be possible to change it to something similar (or to just check the time-sensitive queue first) when starting to dispatch work.

Great, thanks.

[deeprobin]

@stephentoub Can this be closed since the PRs have been merged?

[GSPP]

I have seen the same issue recently with PLINQ.

[snakefoot]

Thank you for fixing this. Looking forward to next .NET 6.0 release.