await Task.Delay(foo); takes seconds instead of ms

Question

Using a variable delay in Task.Delay randomly takes seconds instead of milliseconds when combined with a IO-like operation.

Code to reproduce:

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

namespace ConsoleApplication {
    class Program {
        static void Main(string[] args) {

            Task[] wait = {
                              new delayTest().looper(5250, 20), 
                              new delayTest().looper(3500, 30),
                              new delayTest().looper(2625, 40), 
                              new delayTest().looper(2100, 50)
                          };
            Task.WaitAll(wait);

            Console.WriteLine("All Done");
            Console.ReadLine();
        }
    }
    class delayTest {
        private Stopwatch sw = new Stopwatch();

        public delayTest() {
            sw.Start();
        }

        public async Task looper(int count, int delay) {
            var start = sw.Elapsed;
            Console.WriteLine("Start ({0}, {1})", count, delay);
            for (int i = 0; i < count; i++) {
                var before = sw.Elapsed;
                var totalDelay = TimeSpan.FromMilliseconds(i * delay) + start;
                double wait = (totalDelay - sw.Elapsed).TotalMilliseconds;
                if (wait > 0) {
                    await Task.Delay((int)wait);
                    SpinWait.SpinUntil(() => false, 1);
                }
                var finalDelay = (sw.Elapsed - before).TotalMilliseconds;
                if (finalDelay > 30 + delay) {
                    Console.WriteLine("Slow ({0}, {1}): {4} Expected {2:0.0}ms got {3:0.0}ms", count, delay, wait, finalDelay, i);
                }
            }
            Console.WriteLine("Done ({0}, {1})", count, delay);
        }
    }
}

Also reported this on connect.

---

Leaving old question bellow, for completeness.

I am running a task that reads from a network stream, then delays for 20ms, and reads again (doing 500 reads, this should take around 10 seconds). This works well when I only read with 1 task, but strange things happen when I have multiple tasks running, some with long (60 seconds) delay. My ms-delay tasks suddenly hang half way.

I am running the following code (simplified):

var sw = Stopwatch();
sw.Start()
await Task.Delay(20); // actually delay is 10, 20, 30 or 40;
if (sw.Elapsed.TotalSeconds > 1) {
    Console.WriteLine("Sleep: {0:0.00}s", sw.Elapsed.TotalSeconds);
}

This prints:

Sleep: 11.87s

(Actually it gives the 20ms delay 99% of the time, those are ignored).

This delay is almost 600 times longer than expected. The same delay happens on 3 separate threads at the same time, and they all continue again at the same time also.

The 60 second sleeping task wakes up as normal ~40 seconds after the short tasks finish.

Half the time this problem does not even happen. The other half, it has a consistent delay of 11.5-12 seconds. I would suspect a scheduling or thread-pool problem, but all threads should be free.

When I pause my program during the stuck phase, the main thread stacktrace stands on Task.WaitAll, 3 tasks are Scheduled on await Task.Delay(20) and one task is Scheduled on await Task.Delay(60000). Also there are 4 more tasks Awaiting those first 4 tasks, reporting things like '"Task 24" is waiting on this object: "Task 5313" (Owned by thread 0)'. All 4 tasks say the waiting task is owned by thread 0. There are also 4 ContinueWith tasks that I think I can ignore.

There are some other things going on, like a second console application that writes to the network stream, but one console application should not affect the other.

I am completely clueless on this one. What is going on?

Update:

Based on comments and questions:

When I run my program 4 times, 2-3 times it will hang for 10-15 seconds, 1-2 times it will operate as normal (and wont print "Sleep: {0:0.00}s".)

Thread.Count indeed goes up, but this happens regardless of the hang. I just had a run where it did not hang, and Thread.Count started at 24, wend up to 40 after 1 second, around 22 seconds the short tasks finished normal, and then Thread.Count wend down to 22 slowly over the next 40 seconds.

Some more code, full code is found in the link below. Starting clients:

List<Task> tasks = new List<Task>();

private void makeClient(int delay, int startDelay) {
    Task task = new ClientConnection(this, delay, startDelay).connectAsync();
    task.ContinueWith(_ => {
        lock (tasks) { tasks.Remove(task); }
    });
    lock (tasks) { tasks.Add(task); }
}

private void start() {
    DateTime start = DateTime.Now;
    Console.WriteLine("Starting clients...");

    int[] iList = new[]  { 
        0,1,1,2,
        10, 20, 30, 40};
    foreach (int delay in iList) {
        makeClient(delay, 0); ;
    }
    makeClient(15, 40);
    Console.WriteLine("Done making");

    tasks.Add(displayThreads());

    waitForTasks(tasks);
    Console.WriteLine("All done.");
}

private static void waitForTasks(List<Task> tasks) {
    Task[] waitFor;
    lock (tasks) {
        waitFor = tasks.ToArray();
    }
    Task.WaitAll(waitFor);
}

Also, I tried to replace the Delay(20) with await Task.Run(() => Thread.Sleep(20)) Thread.Count now goes from 29 to 43 and back down to 24, however among multiple runes it never hangs.

With or without ThreadPool.SetMinThreads(500, 500), using TaskExt.Delay by noserati it does not hang. (That said, even switching over 1 line of code sometimes stops it from hanging, only to randomly continue after I restart the project 4 times, but I've tried this 6 times in a row without any problems now).

I've tried everything above with and without ThreadPool.SetMinThreads so far, never made any difference.

Update2: CODE!

Answer 1

Without seeing more code, it's hard to make futher guesses, but I'd like to summarize the comments, it may help someone else in the future:

• We've figured out that the ThreadPool stuttering is not an issues here, as ThreadPool.SetMinThreads(500, 500) didn't help.

• Is there any SynchronizationContext in place anywhere in your task workflow? Place Debug.Assert(SyncrhonizationContext.Current == null) everywhere to check for that. Use ConfigureAwait(false) with every await.

• Is there any .Wait, .WaitOne, .WaitAll, WaitAny, .Result used anywhere in your code? Any lock () { ... } constructs? Monitor.Enter/Exit or any other blocking synchronization primitives?

• Regarding this: I've already replaced Task.Delay(20) with Task.Yield(); Thread.Sleep(20) as a workaround, that works. But yeah, I continue to try to figure out what's going on here because the idea that Task.Delay(20) can shoot this far out of line makes it totally unusable.

  This sounds worrying, indeed. It's very unlikely there's a bug in Task.Delay, but everything is possible. For the sake of experimenting, try replacing await Task.Delay(20) with await Task.Run(() => Thread.Sleep(20)), having ThreadPool.SetMinThreads(500, 500) still in-place.

  I also have an experimental implementation of Delay which uses unamanaged CreateTimerQueueTimer API (unlike Task.Delay, which uses System.Threading.Timer, which in turn uses managed TimerQueue). It's available here as a gist. Feel free to try it as TaskExt.Delay instead of the standard Task.Delay. The timer callbacks are posted to ThreadPool, so ThreadPool.SetMinThreads(500, 500) still should be used for this experiment. I doubt it could make any difference, but I'd be interested to know.