-1

I have a Task which I do not await because I want it to continue its own logic in the background. Part of that logic is to delay 60 seconds and check back in to see if some minute work is to be done. The abbreviate code looks something like this:

public Dictionary<string, Task> taskQueue = new Dictionary<string, Task>();

// Entry point
public void DoMainWork(string workId, XmlDocument workInstructions){

    // A work task (i.e. "workInstructions") is actually a plugin which might use its own tasks internally or any other logic it sees fit. 
    var workTask = Task.Factory.StartNew(() => {
        // Main work code that interprets workInstructions
        // .........
        // .........
        // etc.
    }, TaskCreationOptions.LongRunning);

    // Add the work task to the queue of currently running tasks
    taskQueue.Add(workId, workTask);

    // Delay a period of time and then see if we need to extend our timeout for doing main work code
    this.QueueCheckinOnWorkTask(workId);  // Note the non-awaited task
}

private async Task QueueCheckinOnWorkTask(string workId){

    DateTime startTime = DateTime.Now;

    // Delay 60 seconds
    await Task.Delay(60 * 1000).ConfigureAwait(false);

    // Find out how long Task.Delay delayed for.
    TimeSpan duration = DateTime.Now - startTime; // THIS SOMETIMES DENOTES TIMES MUCH LARGER THAN EXPECTED, I.E. 80+ SECONDS VS. 60

    if(!taskQueue.ContainsKey(workId)){
        // Do something based on work being complete
    }else{
        // Work is not complete, inform outside source we're still working

        QueueCheckinOnWorkTask(workId); // Note the non-awaited task
    }

}

Keep in mind, this is example code just to show a extremely miniminal version of what is going on with my actual program.

My problem is that Task.Delay() is delaying for longer than the time specified. Something is blocking this from continuing in a reasonable timeframe.

Unfortunately I haven't been able to replicate the issue on my development machine and it only happens on the server every couple of days. Lastly, it seems related to the number of work tasks we have running at a time.

What would cause this to delay longer than expected? Additionally, how might one go about debugging this type of situation?

This is a follow up to my other question which did not receive an answer: await Task.Delay() delaying for longer that expected

Ryan Griffith
  • 1,591
  • 17
  • 41

1 Answers1

4

Most often that happens because of thread pool saturation. You can clearly see its effect with this simple console application (I measure time the same way you are doing, doesn't matter in this case if we use stopwatch or not):

public class Program {
    public static void Main() {
        for (int j = 0; j < 10; j++)
        for (int i = 1; i < 10; i++) {
            TestDelay(i * 1000);
        }
        Console.ReadKey();
    }

    static async Task TestDelay(int expected) {
        var startTime = DateTime.Now;
        await Task.Delay(expected).ConfigureAwait(false);
        var actual = (int) (DateTime.Now - startTime).TotalMilliseconds;
        ThreadPool.GetAvailableThreads(out int aw, out _);
        ThreadPool.GetMaxThreads(out int mw, out _);            
        Console.WriteLine("Thread: {3}, Total threads in pool: {4}, Expected: {0}, Actual: {1}, Diff: {2}", expected, actual, actual - expected, Thread.CurrentThread.ManagedThreadId, mw - aw);
        Thread.Sleep(5000);
    }
}

This program starts 100 tasks which await Task.Delay for 1-10 seconds, and then use Thread.Sleep for 5 seconds to simulate work on a thread on which continuation runs (this is thread pool thread). It will also output total number of threads in thread pool, so you will see how it increases over time.

If you run it you will see that in almost all cases (except first 8) - actual time after delay is much longer than expected, in some cases 5 times longer (you delayed for 3 seconds but 15 seconds has passed).

That's not because Task.Delay is so imprecise. The reason is continuation after await should be executed on a thread pool thread. Thread pool will not always give you a thread when you request. It can consider that instead of creating new thread - it's better to wait for one of the current busy threads to finish its work. It will wait for a certain time and if no thread became free - it will still create a new thread. If you request 10 thread pool threads at once and none is free, it will wait for Xms and create new one. Now you have 9 requests in queue. Now it will again wait for Xms and create another one. Now you have 8 in queue, and so on. This wait for a thread pool thread to become free is what causes increased delay in this console application (and most likely in your real program) - we keep thread pool threads busy with long Thread.Sleep, and thread pool is saturated.

Some parameters of heuristics used by thread pool are available for you to control. Most influential one is "minumum" number of threads in a pool. Thread pool is expected to always create new thread without delay until total number of threads in a pool reaches configurable "minimum". After that, if you request a thread, it might either still create new one or wait for existing to become free.

So the most straightforward way to remove this delay is to increase minimum number of threads in a pool. For example if you do this:

ThreadPool.GetMinThreads(out int wt, out int ct);
ThreadPool.SetMinThreads(100, ct); // increase min worker threads to 100

All tasks in the example above will complete at the expected time with no additional delay.

This is usually not recommended way to solve this problem though. It's better to avoid performing long running heavy operations on thread pool threads, because thread pool is a global resource and doing this affects your whole application. For example, if we remove Thread.Sleep(5000) in the example above - all tasks will delay for expected amount of time, because all what keeps thread pool thread busy now is Console.WriteLine statement which completes in no time, making this thread available for other work.

So to sum up: identify places where you perform heavy work on thread pool threads and avoid doing that (perform heavy work on separate, non-thread-pool threads instead). Alternatively, you might consider increasing minimum number of threads in a pool to a reasonable amount.

Evk
  • 98,527
  • 8
  • 141
  • 191
  • Thank you @Evk, this lead me to something I've been trying to track down for quite a while now. I should note that all my `Task.Factory.StartNew()` calls are marked as `LongRunning` (I've updated my example to illustrate that) because they either block using a .Wait() inside of them or because the actual work being performed by the plugin *could* be heavy-lifting (or maybe not, I don't know) and I'm trying to isolate intensive, long running "work" from blocking my threads. Any suggestions on how to approach this would be appreciated. – Ryan Griffith Feb 20 '18 at 21:52
  • And why don't you use 'workTask.ContinueWith(...)'? What's the point in polling every minute if you can be notified immediately? – Evk Feb 21 '18 at 04:18