badflyer


Peter Sulucz - April 2, 19

By default, .Net does not provide performance counters for the built in ThreadPool. Detecting ThreadPool starvation can be extremely difficult. We can use the frameworks internal trace source as a hook to implement some of our own statistics. This post provides an example of how to do just that, by writing out the ThreadPool queue length to the Console.

The ThreadPool does offer internal methods for querying the Queue Length directly, but they are designed to be used by a debugger, so are not thread safe. Ex: ThreadPool.GetQueuedWorkItems();

These are the methods we are interested in on the FrameworkEventSource:

[Event(30, Level = EventLevel.Verbose, Keywords = (EventKeywords)18L)]
public void ThreadPoolEnqueueWork(long workID)

[Event(31, Level = EventLevel.Verbose, Keywords = (EventKeywords)18L)]
public void ThreadPoolDequeueWork(long workID)

The following code snippet demonstrates how to create an in-process EventListener which subscribes to the FrameworkEventSource and keeps track of work item Enqueues and Dequeues. A growing queue can be used to track that the threadpool is having trouble keeping up with the amount of work that is assigned to it. ‘Main’ demonstrates the usage, and a program which starves the ThreadPool by creating work items which sleep in threads for 10 seconds. Ideally, the work done within OnEventWritten should be minimal.

using System;
using System.Diagnostics.Tracing;
using System.Threading;

class Program
{
    static void Main(string[] args)
    {
        using (var eventListener = new ThreadPoolWorkListener())
        {
            // Sleeping in threadpool threads will block them all up very quickly
            for (var i = 0; i < 100; i++)
            {
                ThreadPool.QueueUserWorkItem((a) => Thread.Sleep(10000));
            }

            // So I can read the console output.
            Console.ReadLine();
        }
    }

    /// <summary>
    /// An EventListener which listens to .Net's internal FrameworkEventSource
    /// </summary>
    private class ThreadPoolWorkListener : EventListener
    {
        /// <summary>
        /// The current thread pool length.
        /// </summary>
        private volatile int queueLength = 0;

        /// <summary>
        /// The framework event source.
        /// </summary>
        private EventSource frameworkSource = null;

        /// <summary>
        /// Callback which is called for every event source in the app domain.
        /// </summary>
        /// <param name="eventSource">The event source.</param>
        protected override void OnEventSourceCreated(EventSource eventSource)
        {
            base.OnEventSourceCreated(eventSource);

            // We care about .net's internal framework event source.
            if (eventSource.Name == "System.Diagnostics.Eventing.FrameworkEventSource")
            {
                this.frameworkSource = eventSource;

                // Register for 'Verbose' events with Keywork 18. Which are the threadpool events.
                this.EnableEvents(this.frameworkSource, EventLevel.Verbose, (EventKeywords)(18));
            }
        }

        /// <summary>
        /// Called when every event is written.
        /// </summary>
        /// <param name="eventData">The event data.</param>
        protected override void OnEventWritten(EventWrittenEventArgs eventData)
        {
            // Enqueue work item.
            if (eventData.EventId == 30)
            {
                var len = Interlocked.Increment(ref this.queueLength);
                Console.WriteLine("[{0:hh:mm:ss.ffffff}] Enqueue: {1} Thread pool length {2}", DateTime.UtcNow, eventData.Payload[0], len);
            }
            // Dequeue work item.
            else if (eventData.EventId == 31)
            {
                var len = Interlocked.Decrement(ref this.queueLength);
                Console.WriteLine("[{0:hh:mm:ss.ffffff}] Dequeue: {1} Thread pool length {2}", DateTime.UtcNow, eventData.Payload[0], len);
            }
        }

        /// <summary>
        /// Clean up and unregister.
        /// </summary>
        public override void Dispose()
        {
            if (this.frameworkSource != null)
            {
                // Cleanup.
                this.DisableEvents(this.frameworkSource);
                this.frameworkSource = null;
            }

            base.Dispose();
        }
    }
}

The programs output shows that the ThreadPool becomes very slow to spin up new threads as it detects that it is not making any more progress. With new items only being dequeued every second once the pool is full.

//[06:16:53.866470] Dequeue: 46389784 Thread pool length 76
//[06:16:54.818976] Dequeue: 46391980 Thread pool length 73
//[06:16:54.818976] Dequeue: 46392712 Thread pool length 72
//[06:16:55.820560] Dequeue: 46393444 Thread pool length 71
//[06:16:55.821565] Dequeue: 46394176 Thread pool length 70
//[06:16:56.820340] Dequeue: 46394908 Thread pool length 69
//[06:16:56.821342] Dequeue: 46395640 Thread pool length 68
//[06:16:57.816945] Dequeue: 46396372 Thread pool length 67
//[06:16:57.817923] Dequeue: 46397104 Thread pool length 66
//[06:16:58.821703] Dequeue: 46397836 Thread pool length 65
//[06:16:58.821703] Dequeue: 46398568 Thread pool length 64
//[06:16:59.822980] Dequeue: 46399300 Thread pool length 63
//[06:16:59.822980] Dequeue: 46400032 Thread pool length 62
//[06:17:00.817492] Dequeue: 46400764 Thread pool length 61

While the Task Parallel Library (TPL) uses the .Net ThreadPool by default, another interesting internal trace source to consider is the TPL trace source, ‘System.Threading.Tasks.TplEventSource’, which exposes events such as TaskScheduled and TaskCompleted. Hooking into those using the same method could give more detail on how the TPL is behaving for your application.

More detail for the FrameworkEventSource is available here: frameworkeventsource.cs
More detail for the TPLEventSource is available here: TPLETWProvider.cs