Weird stack trace growth with async/await and TaskCompletionSource

user_1188209 0
Viewed 1767

The following C# code:

class Program
{
    static readonly List<TaskCompletionSource<bool>> buffer = 
                new List<TaskCompletionSource<bool>>();
    static Timer timer;

    public static void Main()
    {
        var outstanding = Enumerable.Range(1, 10)
            .Select(Enqueue)
            .ToArray();

        timer = new Timer(x => Flush(), null, 
                         TimeSpan.FromSeconds(1),
                         TimeSpan.FromMilliseconds(-1));
        try
        {
            Task.WaitAll(outstanding);
        }
        catch {}

        Console.ReadKey();
    }

    static Task Enqueue(int i)
    {
        var task = new TaskCompletionSource<bool>();
        buffer.Add(task);
        return task.Task;
    }

    static void Flush()
    {
        try
        {
            throw new ArgumentException("test");
        }
        catch (Exception e)
        {
            foreach (var each in buffer)
            {
                var lenBefore = e.StackTrace.Length;
                each.TrySetException(e);
                var lenAfter = e.StackTrace.Length;
                Console.WriteLine($"Before - After: {lenBefore} - {lenAfter}");
                Console.WriteLine(e.StackTrace);

            }
        }
    }
}

Produces:

Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149
Before - After: 149 - 149

But when I change Enqueue method to async:

static async Task Enqueue(int i)
{
    var task = new TaskCompletionSource<bool>();
    buffer.Add(task);
    return await task.Task;
}

The result is:

Before - After: 149 - 643
Before - After: 643 - 1137
Before - After: 1137 - 1631
Before - After: 1631 - 2125
Before - After: 2125 - 2619
Before - After: 2619 - 3113
Before - After: 3113 - 3607
Before - After: 3607 - 4101
Before - After: 4101 - 4595
Before - After: 4595 - 5089

It looks like stack trace growth recursively for each buffered item. For the first item exception stack trace will be:

   at Program.Flush() in C:\src\Program.cs:line 41
   --- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotificati...
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Program.<Enqueue>d__3.MoveNext() in C:\src\Program.cs:line 34

While second will look like below and so on:

   at Program.Flush() in C:\src\Program.cs:line 41
   --- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotificati...
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Program.<Enqueue>d__3.MoveNext() in C:\src\Program.cs:line 34
   --- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotificati...
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Program.<Enqueue>d__3.MoveNext() in C:\src\Program.cs:line 34

What is going on here and how to fix it?

async-await task-parallel-library asynchronous .net c#
2 Answers

Short answer: await tries to unwrap result, while method withod await does not try to access task result.

Longer answer:

  1. The recurring part of call stack have the following look:

RecurrringCallStack

  1. The ValidateEnd method of TaskAwaiter is being inlined, and the HandleNonSuccessAndDebuggerNotification causes a call to ThrowForNonSuccess which seems to be inlined too and, as single exception is used to set result for 10 TaskCompletionSources, the reason of growing stack of that exception can be seen here.

Simple solution is to use new Exception("Some descriptive message", originalException) on each TrySetException call.

user_37252000

The issue is you are reusing the same exception for each task, so it appends all the stacks together assuming that is the sequence they progressed in.

If you instead create a new exception for each

var ex = new Exception(e.Message, e);
each.TrySetException(ex);

Then you'll get 

Before - After: 87 - 341
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Program.<Enqueue>d__3.MoveNext() in C:\src\Program.cs:line 34
Before - After: 87 - 341
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Program.<Enqueue>d__3.MoveNext() in C:\src\Program.cs:line 34
Before - After: 87 - 341
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Program.<Enqueue>d__3.MoveNext() in C:\src\Program.cs:line 34
Before - After: 87 - 341

If you also use the Ben.Demystifier library

var ex = new Exception(e.Message, e);
each.TrySetException(ex);
var lenAfter = ex.Demystify().StackTrace.Length;

Then that will come down even further:

Before - After: 87 - 105
   at async Task Program.Enqueue(int i) in C:\src\Program.cs:line 34
Before - After: 92 - 105
   at async Task Program.Enqueue(int i) in C:\src\Program.cs:line 34
Before - After: 92 - 105
   at async Task Program.Enqueue(int i) in C:\src\Program.cs:line 34
Before - After: 92 - 105
user_11099180
Related