4

I have a Windows Service application which uses .Net Tasks heavily. I have a decent understanding of them, but am no pro and am encountering a problem.

I have a situation where my await Task.Delay() takes much longer at times (up to 60 seconds longer) than it should. I'm sure this is due to something I'm doing, but I'm having trouble tracing it down what could influence this.

Here is a much simplified contrived example of the type of thing I'm doing.

public async Task DoDelay(CancellationToken token = default(CancellationToken))
{
    // Delay for then check to see if we need to extend our visibility timeout
    DateTime beforeDelay = DateTime.Now;

    // Wait for 180 seconds, i.e. 3 minutes
    await Task.Delay((int)180 * 1000, token).ConfigureAwait(false);

    // Check to see how long we actually delayed for
    TimeSpan durationOfDelay = DateTime.Now - beforeDelay;

    Trace.WriteLine("Duration: " + durationOfDelay.TotalSeconds.ToString());
}

Sometimes the durationOfDelay can be up to 60 seconds longer than I delayed for.

As some background, there might be multiple other Tasks calling DoDelay() and running at the same time. I've seen that at times, all of the awaited Task.Delay() calls finish at the same time despite having being awaited at different times with the same delay value.

For example:

// Non-awaited call executed at 00:00
DoDelay();

// Non-awaited call executed at 00:10
DoDelay();

// Non-awaited call executed at 00:20
DoDelay();

// Time goes by....
// Trace output:
// "Duration: 200"
// "Duration: 190"
// "Duration: 180"

What would cause this type of thing?

Ryan Griffith
  • 1,591
  • 17
  • 41
  • 5
    Can you provide a [mcve] showing the problem? I'd also strongly recommend using either `Stopwatch` or at least `DateTime.UtcNow` - the first will (I believe) mean that clock synchronization isn't an issue, and the latter will at least avoid DST transitions showing odd results. – Jon Skeet Nov 24 '17 at 15:22
  • 1
    If I were to hazard a guess, you're in a type of application that uses a queue-based synchronization context (Winforms is one such application) and you're blocking the queue, thus the continuation, the part after the await, won't run "when you expect it to" but only after you unblock the queue. – Lasse V. Karlsen Nov 24 '17 at 15:23
  • Why are you awaiting on a thread which you are not awating? If the call to `DoDelay` won't be `await`ed, use `System.Threading.Thread.Sleep()` intead. – Camilo Terevinto Nov 24 '17 at 15:23
  • @CamiloTerevinto No, in a task world he should use Task.Delay and await it. This won't tie up a thread just sitting idle waiting for the sleep to complete but instead queue up a new task to take over when the delay has completed. – Lasse V. Karlsen Nov 24 '17 at 15:24
  • @LasseVågsætherKarlsen But he is not awaiting the called Task... – Camilo Terevinto Nov 24 '17 at 15:24
  • 1
    So? It's a fire-and-forget task, perfectly legal. Not the right choice in most cases but nothing inherently wrong about it. – Lasse V. Karlsen Nov 24 '17 at 15:25
  • Maybe I didn't express correctly. I meant to said "use Thread.Sleep instead of creating a task just to call Task.Delay". It is perfectly legal, I agree, but I fail to understand how it could provide anything useful. – Camilo Terevinto Nov 24 '17 at 15:26
  • 3
    The method runs up until it has created the task for the delay and then returns (void, fire-and-forget). Once the delay has completed, the continuation task which represents the rest of the method containing the writeline and such is executed. If he wants "do this, then wait 3 minutes, then do this other thing", even if he isn't explicitly observing this task any more, then this is a perfectly fine thing to do. Again, fire-and-forget tasks are not the best option but this should work *as expected* in terms of doing what it is supposed to. – Lasse V. Karlsen Nov 24 '17 at 15:28
  • 3
    Please copy and paste a real working example, and please consider posting a [mcve]. Since the code is currently missing a `+` operator in the expression for the WriteLine method call then this is obviously not the code you're trying to run. You also have no mention of the identifier `token` beyond as a parameter. – Lasse V. Karlsen Nov 24 '17 at 15:30
  • @LasseVågsætherKarlsen, that is exactly what I'm doing. – Ryan Griffith Nov 24 '17 at 15:32
  • @RyanGriffith It cannot be exactly what you are doing if it doesn't even compile – Camilo Terevinto Nov 24 '17 at 15:33
  • Unfortunately I cannot provide an example that is verifiable as the code is much larger than shown here and is a plugin-based system. The combinations of things that cause this I have not been able to track down and the behavior is inconsistent, but I know in its most simplest form, await Task.Delay() delays longer than specified at times. – Ryan Griffith Nov 24 '17 at 15:35
  • @JSteward, No, I'm claiming that Task.Delay behaves the same as it does for everyone else, but that there is something influencing the expect result and I'm looking for answers as to what to look into that could influence that result. I.e. could it be thread starvation? If so, how might one look into that? I'm not claiming I have magic code that is different, I'm claiming that I'm not getting the expect result of a small piece of code due to some interference. Where might that interference come from? – Ryan Griffith Nov 24 '17 at 15:44
  • 4
    Is the **real** application also a **console** application or (better question) does the **real** application have something assigned at `System.Threading.SynchronizationContext.Current`? Because then all of the `DoDelay` tasks will wait for the SynchronizationContext and that could cause such things. Try `await Task.Delay((int)180 * 1000, token).ConfigureAwait( false );` – Sir Rufo Nov 24 '17 at 15:53
  • @SirRufo, I updated the question with this information, it is a Windows Service. – Ryan Griffith Nov 24 '17 at 15:57
  • @RyanGriffith Did you try the `ConfigureAwait( false )`? – Sir Rufo Nov 24 '17 at 15:58
  • Might be useless, but what happens if you try something like `Task.Run(Thread.Sleep)` instead of the delay? – IS4 Nov 24 '17 at 16:00
  • 8
    "Using tasks heavily" is enough to explain this problem. The continuation after the Delay() call runs on a thread-pool thread. Which competes with everything else that is asking the pool for service. If you have tasks that gum-up the pool, blocking for a long time without the TaskCreationOptions.LongRunning option then it can take a while for code to resume running. One way to diagnose this is by using Threadpool.SetMinThreads(), raising the minimum considerably. Not a proper fix, you'd need tracing and/or the Debug > Windows > Threads window to find the slow code. – Hans Passant Nov 24 '17 at 16:03
  • @SirRufo, `ConfigureAwait(false)` did not work. I will update my question to reflect using that. – Ryan Griffith Nov 24 '17 at 17:10
  • Is your CPU at 100% when this happens? You could take a memory dump when your task did wait much longer to check what other threads were doing. E.g. Procdump -ma ddd where ddd is your process id should help to get down to the root cause. It is an exe from Sysinternals. – Alois Kraus Nov 24 '17 at 17:22
  • @HansPassant, how might I determine if my task is blocked or my thread pool is having issues with competing thread resources? I'm fairly certain that there is something blocking the Task.Delay call from completing on time, but where to begin to debug this is beyond me at this point. – Ryan Griffith Nov 25 '17 at 22:03

0 Answers0