Why the async await not working as expected

Question

I am learning TPL (async/await) from a tutorial and I tried to test it out myself using a console application. Please don't be offended by my ignorance. I am sure I am doing wrong somewhere- I wrote the following code:

static void Main(string[] args_)
{
    Task<int> task = ProcessNumber(25);
    Console.WriteLine(string.Format("{0}: Waiting started...", DateTime.Now));
    task.Wait();
    Console.WriteLine(string.Format("{0}: Waiting ended...", DateTime.Now));
    Console.WriteLine(task.Result);

    Console.WriteLine("Press any key to terminate!");
    Console.ReadLine();
}

static async Task<int> ProcessNumber(int i_)
{
    Thread.Sleep(1000);
    var integer = await IncrementNumber(i_ * 23);
    return integer;
}

static async Task<int> IncrementNumber(int j_)
{
    Thread.Sleep(6000);
    return (j_ + 23) / 23;
}

It's plain C# console code. My question is why do I get following output:

3/5/2015 5:22:37 PM: Waiting started...
3/5/2015 5:22:37 PM: Waiting ended...
26

Shouldn't there be considerable time gap between"Waiting started" and "Waiting Ended"?

UPDATE

After the answers, I figured out that Task.Delay(..) and Thread.Sleep(..) aren't same because they work very differently. Here is a nice link that explains with an example.

Seems it would be a mistake to consider TPL as yet another framework for multithreading. All the answers helped me , so I voted for all. However, I select Jon's answer as it is the most illustrative and the first one to appear. Thanks all!

Always pay attention to the compiler warnings. For this code, the compiler will give you a warning telling you exactly what's wrong. — Stephen Cleary, Mar 05 '15 at 13:35

Jon Skeet · Accepted Answer · 2015-03-05T12:05:32.703

No, because in fact you're sleeping for 7 seconds before you print Waiting started. Here's what happens:

Main calls ProcessNumber
ProcessNumber sleeps for 1 second
ProcessNumber calls IncrementNumber
IncrementNumber sleeps for 6 seconds
IncrementNumber performs a computation, then returns a completed task
ProcessNumber awaits that completed task, and continues
ProcessNumber returns a completed task
Main prints "Waiting started"
Main waits for the already-completed task to complete (no-op)
Main prints "Waiting ended"

If you change each Thread.Sleep to

await Task.Delay(...);

then you'll see what you expect. The new flow will be:

Main calls ProcessNumber
ProcessNumber calls Task.Delay and awaits the result...
... and because it hasn't completed yet, ProcessNumber returns an ongoing task to Main
Main prints "Waiting started"
Main waits for the task returned by ProcessNumber to complete
The Task.Delay task completes
The continuation in ProcessNumber starts to execute...
ProcessNumber calls IncrementNumber
IncrementNumber calls Task.Delay and awaits the result...
... and because it hasn't completed yet, IncrementNumber returns an ongoing task to ProcessNumber
ProcessNumber awaits the task, which hasn't completed, so the continuation exits.
The second delay task completes
The continuation within IncrementNumber executes
It reaches the end of IncrementNumber, and sets the result of the associated task
The continuation in ProcessNumber (which was awaiting that task) now executes
It reaches the end of ProcessNumber, and sets the result of the associated task
The call to Task.Wait in Main completes
Main prints "Waiting ended" etc

It's really important to understand that until an async method hits the first await where it actually needs to pause (because the thing it's awaiting hasn't completed), it executes synchronously. It's not like calling an async method splits off into a different thread.

Thanks Jon for the answer- the await Task.Delay(..) solution worked perfect. Further to that I changed the Thread.Sleep code thus: static async Task SleepForMilSec(int milSec_){Thread.Sleep(milSec_); Now rather than the direct Thread.Sleep call in ProcessNumber and IncrementNumber methods, I use await SleepForMilSec(..). There is still only delay of 6 seconds. Which means: it is getting blocked for the first await call in ProcessNumber method. Any idea? Edit: By the way your course on async await in Pluralsight is the next tutorial I am going to follow. :) — James, Mar 05 '15 at 12:25
@James: Your `SleepForMilSec` method should have a warning saying that you've got an async method with no awaits, and it's therefore going to execute synchronously. Take note of that :) — Jon Skeet, Mar 05 '15 at 12:41
Yess..I noted that warning and I have updated the question too! Thanks Jon. That was very helpful! — James, Mar 05 '15 at 12:46

score 3 · Answer 2 · edited May 23 '17 at 12:06

It is because none of your methods are asynchronous. They pretend to be asynchronous by returning Task but they all execute synchronously.

In fact you should be getting the compiler warning for IncrementNumber number saying This async method lacks 'await' operators and will run synchronously... etc. It basically says that your method will be executed synchronously. This answer explains it in detail.

So when ProcessNumber returns the whole nested methods calls are already finished synchronously.

Change the method to use await Task.Delay instead of Thread.Sleep to make it asynchronous.

score 1 · Answer 3 · answered Mar 05 '15 at 12:12

you need to refactor your code. like this

    static async Task<int> IncrementNumber(int j_)
{
    await Task.Delay(...);
    return (j_ + 23) / 23;
}

a function with keyword async must have at least one await inside the body in order to run function async.
Thread.Sleep(...) is also responsible for this.

if you found CPU bound task instead of Thread.Sleep then you need to do something like this.

//it will create a new thread then sleep.
await Task.Run( () => (  CPUBoundTask());
var integer = await IncrementNumber(i_ * 23);
return integer;

Why the async await not working as expected

3 Answers3