What would cause a method marked with async to execute synchronously, even though it contains an await call?

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.

Solution

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.