2

I'm trying to debug some code my coworker wrote while he is away.

Here's the call:

var sw = Stopwatch.StartNew();
logger.Trace("Time A: {0}ms", sw.ElapsedMilliseconds); // Roughly 0ms
pt.Task = ProcessMetricsWorker(pt.CancelTokenSource);
sw.Stop();
logger.Trace("Time B: {0}ms", sw.ElapsedMilliseconds); // Over 20000ms!

Here's the method signature:

async Task ProcessMetricsWorker(CancellationTokenSource cancelTokenSource)

The method takes around 20 seconds to run and according to logging I place immediately before and after the first line quoted above, the task is executing synchronously, as though the async part is being ignored. What would cause this to happen?

Note that there is an await call inside the async method. It's inside a while loop, though I can't imagine that would make a difference.

// internal to the method referenced above
result = await metricProcessor.ProcessItem(domain);

Also, I created a small test app that runs a very simple async/await setup to make sure that await actually works on the server I'm running it on, and it does work correctly in my small test case, just not in the main app I'm trying to debug.

Nathan Ridley
  • 33,766
  • 35
  • 123
  • 197

2 Answers2

4

Every async method is started as a regular method call. It only becomes asynchronous (in the sense of yielding to its caller) the first time it does an await on an awaitable (that is not already completed).

So, there's a couple possibilities of what's going on in ProcessMetricsWorker:

  • It may contain some long-running synchronous code before the first await.
  • Many of the first awaitables that it awaits may already be completed. If they are all already completed, then ProcessMetricsWorker is actually synchronous.

The "fast path" blog post contains more details of how an await is converted to code, and shows how it only yields if it acts on a non-completed awaitable.

Stephen Cleary
  • 437,863
  • 77
  • 675
  • 810
0

Well, I think I found a bug in the Async CTP.

I added this method:

async Task DummyTask()
{
    await TaskEx.Run(() => Thread.Sleep(1000));
}

Then added this right inside the ProcessMetricsWorker method:

await DummyTask();

And hey presto, the method is now asynchronous! I'm wondering if the compiler somehow ignored the inner await call in the method and it all came out synchronous in the MSIL code...

Nathan Ridley
  • 33,766
  • 35
  • 123
  • 197
  • 1
    I'm going to guess that you put this right at the beginning of the function. If that's the case, it would indicate that your function is just doing a lot of work before doing its first await. – Gabe Jan 06 '12 at 14:47