Tags

Stack traces from async methods in .NET

Microsoft's .NET stack has one of the two best implementations of asynchronous code through coroutines that I've seen, and the only one actually available for me to use. (The other is some weird stuff Valve have internally within Steam.)

.NET's task-based asynchronous APIs follow a similar idea behind promises, except they have added syntactical sugar and runtime support to make this dead easy to use. For example, to download a file from the internet asynchronously I can write a method such as this:

Note that Foo()awaits the task it returns - which will generate a new Task - where as Bar() simply returns the task of the method it calls.

If I run this with dotnet run foo, the stack trace includes Foo:

Unhandled Exception: System.InvalidOperationException: aaaaaaah
at stacktrace.Program.<BlowUp>d__4.MoveNext() in /private/tmp/stacktrace/Program.cs:line 37
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at stacktrace.Program.<Foo>d__2.MoveNext() in /private/tmp/stacktrace/Program.cs:line 30
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at stacktrace.Program.<MainAsync>d__1.MoveNext() in /private/tmp/stacktrace/Program.cs:line 17
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
at stacktrace.Program.Main(String[] args) in /private/tmp/stacktrace/Program.cs:line 10

If we eliminate the runtime frames from the compiler-generated state machine, we get the following "real" stack trace:

Unhandled Exception: System.InvalidOperationException: aaaaaaah
at stacktrace.Program.<BlowUp>d__4.MoveNext() in /private/tmp/stacktrace/Program.cs:line 37
at stacktrace.Program.<Foo>d__2.MoveNext() in /private/tmp/stacktrace/Program.cs:line 30
at stacktrace.Program.<MainAsync>d__1.MoveNext() in /private/tmp/stacktrace/Program.cs:line 17
at stacktrace.Program.Main(String[] args) in /private/tmp/stacktrace/Program.cs:line 10

From this we can see, reading top-to-bottom that Main() called MainAsync() which called Foo(), which in turn called BlowUp(). This matches our source code, and all is good.

On the other hand, if I run dotnet run bar, we get this stack trace:

Unhandled Exception: System.InvalidOperationException: aaaaaaah
at stacktrace.Program.<BlowUp>d__4.MoveNext() in /private/tmp/stacktrace/Program.cs:line 37
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at stacktrace.Program.<MainAsync>d__1.MoveNext() in /private/tmp/stacktrace/Program.cs:line 21
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
at stacktrace.Program.Main(String[] args) in /private/tmp/stacktrace/Program.cs:line 10

Again if we strip out the compiler-generated runtime stuff, we get:

Unhandled Exception: System.InvalidOperationException: aaaaaaah
at stacktrace.Program.<BlowUp>d__4.MoveNext() in /private/tmp/stacktrace/Program.cs:line 37
at stacktrace.Program.<MainAsync>d__1.MoveNext() in /private/tmp/stacktrace/Program.cs:line 21
at stacktrace.Program.Main(String[] args) in /private/tmp/stacktrace/Program.cs:line 10

If we look at this stack trace, Main() called MainAsync(), which then called BlowUp(). This can be confusing, as according to the source code, MainAsync() has no calls to BlowUp(). The stack trace for Bar() has completely vanished.

Always awaiting a Task ensures that every single method along the way forms part of the stack trace, and lets developers easily locate not only the piece of code that threw the exception, but how we got to it in the first place.

If all we had to go off here was that BlowUp() exploded, we wouldn't be able to tell if we had called BlowUp(true) or BlowUp(false). By knowing the previous stack frame, we can see what arguments would have been passed to it.

As always in software development there is a tradeoff here. Every single use of await causes more compiler-generated code for the asynchronous state machine, which increases the size of the compiled binaries slightly and has a slight runtime overhead. These are tradeoffs that I am willing to make, though, to save hours of later debugging time.