Strange behaviour with async operations inside System.Threading.Timer

Question

Short intro: I have a windows service which monitors other applications and services if they are functional at various time intervals. The service uses one timer (System.Threading.Timer) for every monitored application (named as "monitor"). Different types of applications require different types of monitors, some work synchronously and others asynchronous (for example, those using HttpClient).

So I got to the point where I would need asynchronous calls in a timer. I have simplified the code to the limit so that I can post it here. It can be run directly into a console project. My problem is that this code has a very bizarre behavior, as more timers are introduced - the harder it runs until it does not respond at all (over 20 timers). Does not the monitor run time be exactly the delay set in asynchronous operation (100ms)?

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;

namespace TestMain
{
    class TestMain
    {
        private static List<TestTimer> timers = new List<TestTimer>();

        static void Main(string[] args)
        {
            for (int i = 0; i < 20; i++)
            {
                TestMain.timers.Add(new TestTimer(i));
            }
            Console.WriteLine("Press [Enter] to exit.");
            Console.ReadLine();
        }

        public class TestTimer
        {
            public Int32 Id { get; private set; }
            private Timer timer;

            public TestTimer(Int32 id)
            {
                this.Id = id;
                this.timer = new Timer(this.Test, null, 1000, 30 * 1000);
            }

            private void Test(Object state)
            {
                TestWorker t = new TestWorker(this.Id);
                t.Run();
            }
        }

        public class TestWorker
        {
            public Int32 Id { get; private set; }
            private Stopwatch sw = new Stopwatch();

            public TestWorker(Int32 id) { this.Id = id; }

            public void Run()
            {
                this.RunAsync().Wait();
            }
            private async Task RunAsync()
            {
                this.Log(String.Format("Start[{0,2}]", this.Id));
                this.sw.Restart();

                await Task.Run(() => { System.Threading.Thread.Sleep(100); }).ConfigureAwait(false);

                this.sw.Stop();
                this.Log(String.Format("  End[{0,2}]   Duration=[{1}]", this.Id, (Int32)this.sw.ElapsedMilliseconds));
            }
            private void Log(String text)
            {
                Console.WriteLine(String.Format("{0,20}  {1}", DateTime.Now, text));
            }

        }
    }
}

I attached a printscreen with a run. Console Printscreen

The solution of no longer waiting after the asynchronous operation completes some of the problem but there are still bottlenecks between the threads. The right solution for me is the one that uses ThreadPool.SetMinThreads because it is scalable over time because at the start of the service all the applications (number and types) that need to be monitored are known and the minimum number of threads can be set accordingly. Thank you for the answers. — Adrian Dumitrascu, Nov 09 '17 at 12:05

Evk · Accepted Answer · 2017-11-09T09:55:04.893

That's because of how thread pool managed its threads. Thread pool has "minimal" number of threads (which you can read with ThreadPool.GetMinThreads). By default (that depends on .NET version but we won't complicate stuff with that) it's related to the number of processor cores, for example on my machine that's 8. When those 8 threads are busy and you need more - thread pool will first wait for some time for one of the busy threads to be available (it will wait for about 1 second) and if no thread is available - it will add one more thread to the pool.

Timer callback executes on thread pool. So when all 20 of your timers fire their callback at the same time - only 8 (in my case) callbacks are executed. The rest are queued and one executes approximately every second (they request thread from thread pool to execute but it waits 1 second every time, because all threads in thread pool are busy at the moment). They are busy because your timer callback waits for RunAsync to complete with Wait(). So only after 12 (20-8) seconds all timer callbacks has executed.

When timer callback executes - it writes Start message to console and starts the Stopwatch. Then you request another thread from thread pool by doing Task.Run. All those requests are queued after timer callbacks, so only after all timers are started you start to receive End messages.

So now you have 20 threads busy with waiting for RunAsync to complete. First Task.Run requests another thread. This thread waits for 100 milliseconds and after that it's free and can be reused, so task pool will not create new threads for each Task.Run and will reuse this one (because 100 milliseconds is less that 1 second it will wait for a thread to become available).

To make this behavior more expected - set minimal threads in thread pool with ThreadPool.SetMinThread to some bigger value or don't hold timer callback thread with waiting for RunAsync to complete.

score 0 · Answer 2 · answered Nov 09 '17 at 09:48

System.Threading.Timer is using thread pool, so there is a limit on number of threads and this is what you experience.

Does not the monitor run time be exactly the delay set in asynchronous operation (100ms)?

That's what you want, but it seems the thread is busy for a duration of waiting for task to complete and even more, because the task inside also want to use thread from thread pool.

A quick fix is to use fire-and-forget method (credits), this way timer is not waiting for anything, instead of

public void Run()
{
    RunAsync().Wait();
}

do

public void Run()
{
    #pragma warning disable 4014
    RunAsync();
    #pragma warning restore 4014
}

Strange behaviour with async operations inside System.Threading.Timer

2 Answers2