.net async abnormal behavior

Question

I have an abnormal behavior on WPF MainWindow ctor. I am using an asynchronous method to make a long task, but this task named 'DoAsync' is not complete ! I found a workaround but i don't understood why the code fails :( Here the two calls and the results :

    /// <summary>
/// Interaction logic for MainWindow.xaml
/// </summary>
public partial class MainWindow : Window
{
    static void WriteToOutput(string message, int increment = 0)
    {
        var nw = DateTime.Now;
        var msg = string.Format("{0}.{1:d3} - thread {2:d1}[0x{3:x4}] |\t{4}{5}",
                                    nw.ToString("hh:mm:ss"),
                                    nw.Millisecond,
                                    System.Threading.Thread.CurrentThread.ManagedThreadId,
                                    AppDomain.GetCurrentThreadId(),
                                    new string(' ', 4 * increment),
                                    message
                                );

        System.Diagnostics.Debug.WriteLine(msg);
    }

    public async Task DoAsync()
    {
        WriteToOutput("DoAsync: begin", 2);
        await Task.Delay(1);                    // enforces asynchronism
        WriteToOutput("DoAsync: job begin", 3);
        System.Threading.Thread.Sleep(5000);    // simulates some job ;)
        WriteToOutput("DoAsync: job end", 3);
        WriteToOutput("DoAsync: end", 2);
    }

    private void NormalBehavior()
    {
        WriteToOutput("NormalBehavior: begin", 0);

        Task.Run(async () =>
        {
            WriteToOutput("NormalBehavior_DoAsync: begin", 1);
            await DoAsync();
            WriteToOutput("NormalBehavior_DoAsync: end", 1);
        });

        WriteToOutput("NormalBehavior: sleeping", 0);
        System.Threading.Thread.Sleep(10000);       // to see what happens
        WriteToOutput("NormalBehavior: terminated", 0);
    }

    /// <summary>
    /// Seems the simplest solution, but it fails :( Why ?
    /// </summary>
    private void AbnormalBehavior()
    {
        WriteToOutput("AbnormalBehavior: begin", 0);

        WriteToOutput("AbnormalBehavior_DoAsync: begin", 1);
        var tsk = DoAsync();
        WriteToOutput("AbnormalBehavior_DoAsync: end", 1);

        WriteToOutput("AbnormalBehavior: sleeping", 0);
        System.Threading.Thread.Sleep(10000);       // to see what happens
        WriteToOutput("AbnormalBehavior: terminated", 0);
    }

    public MainWindow()
    {
        NormalBehavior();
        //  Output:
        //  05:18:00.833 - thread 8[0x3818] |   NormalBehavior: begin
        //  05:18:00.842 - thread 8[0x3818] |   NormalBehavior: sleeping
        //  05:18:00.846 - thread 9[0x2274] |       NormalBehavior_DoAsync: begin
        //  05:18:00.848 - thread 9[0x2274] |           DoAsync: begin
        //  05:18:00.853 - thread 10[0x0778] |              DoAsync: job begin
        //  05:18:05.855 - thread 10[0x0778] |              DoAsync: job end
        //  05:18:05.856 - thread 10[0x0778] |          DoAsync: end
        //  05:18:05.856 - thread 10[0x0778] |      NormalBehavior_DoAsync: end
        //  05:18:10.843 - thread 8[0x3818] |   NormalBehavior: terminated
        //_________________________________________________________________

        AbnormalBehavior();
        //  Output:
        //  05:18:10.845 - thread 8[0x3818] |   AbnormalBehavior: begin
        //  05:18:10.846 - thread 8[0x3818] |       AbnormalBehavior_DoAsync: begin
        //  05:18:10.847 - thread 8[0x3818] |           DoAsync: begin
        //  05:18:10.849 - thread 8[0x3818] |       AbnormalBehavior_DoAsync: end
        //  05:18:10.850 - thread 8[0x3818] |   AbnormalBehavior: sleeping
        //  05:18:20.853 - thread 8[0x3818] |   AbnormalBehavior: terminated
        //_________________________________________________________________

        InitializeComponent();
    }
}

Anybody already found this problem or has an explanation ?

Answer 1

Stephen you are right, after the 'AbnormalBehavior' last sleep I can see "DoAsync: job begin" & "DoAsync: job end" all done by the main thread ! Effectively it's the same thread (main thread) which do all the work and as you say it can't do the 'job' while it's sleeping :| Even more, same code is running as I expected on a console program ! As you see in this case it's an other thread (worker thread) which do the job ! Perhaps because it doesn't need to capture the context !?

class Program
{
    static DateTime _Start = new DateTime(0);

    static void WriteToOutput(string message, int increment = 0, bool start = false)
    {
        var nw = DateTime.Now;
        if (start) _Start = nw;
        var spn = nw - _Start;

        var msg = string.Format("{0,2:d}.{1:d3} - thread {2,2:d1}[0x{3:x4}] |\t{4}{5}",
                                    (int)Math.Floor(spn.TotalSeconds),
                                    spn.Milliseconds,
                                    System.Threading.Thread.CurrentThread.ManagedThreadId,
                                    AppDomain.GetCurrentThreadId(),
                                    new string(' ', 4 * increment),
                                    message
                                );

        if (start) msg = "\n" + msg;
        //System.Diagnostics.Debug.WriteLine(msg);
        Console.WriteLine(msg);
    }

    public static async Task DoAsync()
    {
        WriteToOutput("DoAsync: begin", 2);
        await Task.Delay(1);                    // enforces asynchronism
        WriteToOutput("DoAsync: job begin", 3);
        System.Threading.Thread.Sleep(5000);    // simulates some job ;)
        WriteToOutput("DoAsync: job end", 3);
        WriteToOutput("DoAsync: end", 2);
    }

    /// <summary>
    /// It works correctly but it uses more resources and run more slowly :o
    /// </summary>
    /// <returns></returns>
    public static Task DoRescueAsync()
    {
        WriteToOutput("DoAsync: begin", 2);
        return Task.Run(() => {
            WriteToOutput("DoAsync: job begin", 3);
            System.Threading.Thread.Sleep(5000);    // simulates some job ;)
            WriteToOutput("DoAsync: job end", 3);
            WriteToOutput("DoAsync: end", 2);
        });
    }

    private static void NormalBehavior()
    {
        WriteToOutput("NormalBehavior: begin", 0, true);

        Task.Run(async () =>
        {
            WriteToOutput("NormalBehavior_DoAsync: begin", 1);
            await DoAsync();
            WriteToOutput("NormalBehavior_DoAsync: end", 1);
        });

        WriteToOutput("NormalBehavior: sleeping", 0);
        System.Threading.Thread.Sleep(10000);       // to see what happens
        WriteToOutput("NormalBehavior: terminated", 0);
    }

    /// <summary>
    /// Seems the simplest solution, but it fails :( Why ?
    /// </summary>
    private static void AbnormalBehavior()
    {
        WriteToOutput("AbnormalBehavior: begin", 0, true);

        WriteToOutput("AbnormalBehavior_DoAsync: begin", 1);
        var tsk = DoAsync();
        WriteToOutput("AbnormalBehavior_DoAsync: end", 1);

        WriteToOutput("AbnormalBehavior: sleeping", 0);
        System.Threading.Thread.Sleep(10000);       // to see what happens
        WriteToOutput("AbnormalBehavior: terminated", 0);
    }

    static void Main(string[] args)
    {
        NormalBehavior();
        // Output:
        //   0.000 - thread  1[0x34cc] |    NormalBehavior: begin
        //   0.014 - thread  1[0x34cc] |    NormalBehavior: sleeping
        //   0.019 - thread  3[0x0bdc] |        NormalBehavior_DoAsync: begin
        //   0.024 - thread  3[0x0bdc] |            DoAsync: begin
        //   0.029 - thread  4[0x1568] |                DoAsync: job begin
        //   5.045 - thread  4[0x1568] |                DoAsync: job end
        //   5.050 - thread  4[0x1568] |            DoAsync: end
        //   5.053 - thread  4[0x1568] |        NormalBehavior_DoAsync: end
        //  10.018 - thread  1[0x34cc] |    NormalBehavior: terminated
        //_________________________________________________________________

        AbnormalBehavior();     // now CORRECT as expected !
        // Output:
        // 0.000 - thread  1[0x34cc] |    AbnormalBehavior: begin
        // 0.008 - thread  1[0x34cc] |        AbnormalBehavior_DoAsync: begin
        // 0.029 - thread  1[0x34cc] |            DoAsync: begin
        // 0.037 - thread  1[0x34cc] |        AbnormalBehavior_DoAsync: end
        // 0.043 - thread  1[0x34cc] |    AbnormalBehavior: sleeping
        // 0.047 - thread  3[0x0bdc] |                DoAsync: job begin
        // 5.062 - thread  3[0x0bdc] |                DoAsync: job end
        // 7.306 - thread  3[0x0bdc] |            DoAsync: end
        //10.057 - thread  1[0x34cc] |    AbnormalBehavior: terminated
        //_________________________________________________________________

        Console.Write("\nHit a key to close console: "); Console.ReadKey();
    }
}

Answer 2

If you let it run longer, I expect you'll see DoWork's "job begin" and other messages in your debug window.

This is expected behavior for async/await. In particular, await will capture the current "context" - which in the "abnormal" case is the UI context - and will resume on that context. I explain the mechanics of async/await in more detail on my blog.

The other thing of note with this code is that Thread.Sleep blocks the current thread. In particular, when Thread.Sleep runs on the UI thread, that thread is blocked, and cannot execute other code.

Task.Run will execute the specified code on a thread pool thread, where there is no UI context, and any await in that case will resume on a thread pool thread.

Thus, with your first ("working") example, DoAsync runs on a thread pool thread and blocks a thread pool thread for 5 seconds. In the meantime, NormalBehavior blocks the UI thread for 10 seconds.

With the second ("failing") example, AbnormalBehavior runs DoAsync on the UI thread. As soon as DoAsync hits its await, AbnormalBehavior continues running and blocks the UI thread for 10 seconds. Only then is DoAsync able to resume on the UI thread and block it for 5 seconds.