How long should QueueUserWorkItem take to execute?

问题:

The application I am developing processes data in consumer threads from a Blocking collection when it is done processing the data (never any more than 1ms) it spins that processed data off into a new thread from the ThreadPool to be sent to my users and stored in the database.

I start a stopwatch just before I call ThreadPool.QueueUserWorkItem and stop it as one of the first things I do in the function called by ThreadPool.QueueUserWorkItem (any code before this has been clocked at less than 1ms).

The time this stopwatch is reporting is worrying me a little, the average time is 4ms (no problem there) but the max is upwards of 900ms, the least threads ever used is 1, the most used is ~60 and the average is ~40.

Although as long as the average stays the same it should not be a problem I would love to know why I get the occasional ~1sec wait for a thread when I normally have 900+ free.

Some example code that will run independently with sleeps replacing actual processing:

using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Text;
using System.Threading;
using System.Threading.Tasks;

namespace ConsoleApplication2
{
    class Program
    {
        static int[] AvailableThreads;
        static Stopwatch[] stopwatch;
        static BlockingCollection<int> Queue;
        static ManualResetEvent consumerEvent;
        static ManualResetEvent alldone;
        static bool disposed = false;

        static void Main(string[] args)
        {
            int iterations = 10000;
            stopwatch = new Stopwatch[iterations];
            AvailableThreads = new int[iterations];
            Queue = new BlockingCollection<int>();
            consumerEvent = new ManualResetEvent(false);
            alldone = new ManualResetEvent(false);

            Thread processThread = new Thread(new ThreadStart(ProcessThread));
            processThread.IsBackground = true;
            processThread.Start();

            int MaxThreads = 0;
            int y = 0;

            ThreadPool.GetMaxThreads(out MaxThreads, out y);

            for (int i = 0; i < stopwatch.Length; i++)
            {
                Queue.Add(i);
                consumerEvent.Set();
            }

            alldone.Reset();
            alldone.WaitOne();

            long av = 0;
            long max = 0;

            int threadsAv = 0;
            int threadsMax = 0;

            for (int i = 0; i < stopwatch.Length; i++)
            {
                long ms = stopwatch[i].ElapsedMilliseconds;
                av += ms;
                threadsAv += AvailableThreads[i];
                if (max < ms) max = ms;
                if (threadsMax < AvailableThreads[i]) threadsMax = AvailableThreads[i];
            }

            if(av != 0) av = av / stopwatch.Length;

            if (threadsAv != 0) threadsAv = threadsAv / stopwatch.Length;

            Console.WriteLine("Average Time: {0}, Max Time: {1}, Max Thread: {2}, Average Available Threads: {3}, Max Available Threads: {4}", av, max, MaxThreads, threadsAv, threadsMax);

            Console.ReadLine();

            disposed = true;
        }

        static void ProcessThread()
        {
            while (!disposed)
            {
                foreach (int i in Queue.GetConsumingEnumerable())
                {
                    if (disposed) return;
                    // Proccess a bit of data here .....
                    stopwatch[i] = new Stopwatch();
                    stopwatch[i].Start();
                    int y = 0;
                    ThreadPool.GetAvailableThreads(out AvailableThreads[i], out y);
                    ThreadPool.QueueUserWorkItem(TransmitThread, i);
                }

                consumerEvent.Reset();
                consumerEvent.WaitOne();
            }
        }

        static void TransmitThread(object data)
        {
            int i = (int)data;
            stopwatch[i].Stop();
            //Fake some work.

            Thread.Sleep(1);

            if (i == stopwatch.Length - 1) alldone.Set();
        }
    }
}

Example output:

Average Time: 581, Max Time: 1126, Max Thread: 1023, Average Available Threads: 1015, Max Available Threads: 1023

Can anyone provide some insight on this?

回答1:

I can confirm that the issue is with the throttling incurred from exceeding the min value on the thread pool, increasing this number significantly improves performance.

You can increase the minimum number of threads that will be created immediately. The only negative consequence this has is that it might result in higher memory usage in case your workload does not need those threads for a long time. This is a valid solution to your problem.

On the other hand: Why do you have hundreds or even thousands (?) of threads running?! This is certainly supported and not unreliable. But it is very unusual and hints at architectural problems. Consider using async IO and async waiting. You don't have to make everything async. Just those places where most of the time blocking is spent. Probably there are a handful of places that cause 99% of the blocking. Make those async and your thread counts are down to normal levels.

回答2:

The point of the ThreadPool is not to get a work item running right away. The point is to run the optimum number of threads. Which, by default, is the number of execution cores the processor has available. If you run more active threads than you have cores then you get less work done. The operating system is forced to context-switch active threads onto cores, that's overhead that reduces the total number of machine cycles that get dedicated to executing code.

So seeing a 900 msec delay is nothing remarkable. You simply had too many active QUWI work items active at the time. The one you added will get serviced, eventually.

This is, in general, a sign of a firehose problem. You are asking the machine to do more than it can do. That's pretty normal, the ThreadPool keeps you out of trouble by delaying to work so these threads cannot use too many resources and crash your program with, say, an OutOfMemoryException.

Seeing 40 to 60 threads active is a workaround that ThreadPool uses when it thinks that work items are stuck. Every 0.5 seconds it allows an extra thread to start to make up for that. The simplest way to see that your work items are stuck on non-productive work is to look at the processor utilization in Task Manager. If it is not 100% then threads are blocking too much. Such threads are not great candidates for the thread pool, they are better serviced by a Thread or a long-running Task. Changing the default minimum number of threads is a workaround, a rather crude one however. You are a bit shy of having to panic about that, hard to tell since your code is fake.