Why the async await not working as expected

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!

Jon Skeet
people
quotationmark

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.

people

See more on this question at Stackoverflow