Skip to content

High performance understanding for stack traces (Make error logs more productive)

License

Notifications You must be signed in to change notification settings

benaadams/Ben.Demystifier

Repository files navigation

Ben.Demystifier

NuGet version (Ben.Demystifier) build

Output the modern C# 7.0+ features in stack traces that looks like the C# source code that generated them rather than IL formatted.

High performance understanding for stack traces

.NET stack traces output the compiler transformed methods; rather than the source code methods, which make them slow to mentally parse and match back to the source code.

The current output was good for C# 1.0; but has become progressively worse since C# 2.0 (iterators, generics) as new features are added to the .NET languages and at C# 7.1 the stack traces are esoteric (see: Problems with current stack traces).

Make error logs more productive

Output the modern C# 7.0+ features in stack traces in an understandable fashion that looks like the C# source code that generated them.

Demystified stacktrace

Usage

exception.Demystify()

Or instead of Environment.StackTrace

EnhancedStackTrace.Current()

Resolves the stack back to the C# source format of the calls (and is an inspectable list of stack frames)

Calling .ToString() on the Demystified exception will produce a string stacktrace similar to the following (without the comments):

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at bool System.Collections.Generic.List<T>+Enumerator.MoveNextRare()
   at IEnumerable<string> Program.Iterator(int startAt)+MoveNext()                       // Resolved enumerator
   at bool System.Linq.Enumerable+SelectEnumerableIterator<TSource, TResult>.MoveNext()  // Resolved enumerator
   at string string.Join(string separator, IEnumerable<string> values)                    
   at string Program+GenericClass<TSuperType>.GenericMethod<TSubType>(ref TSubType value) 
   at async Task<string> Program.MethodAsync(int value)                                  // Resolved async 
   at async Task<string> Program.MethodAsync<TValue>(TValue value)                       // Resolved async 
   at string Program.Method(string value)+()=>{} [0]                                     // lambda source + ordinal
   at string Program.Method(string value)+()=>{} [1]                                     // lambda source + ordinal 
   at string Program.RunLambda(Func<string> lambda)                                       
   at (string val, bool) Program.Method(string value)                                    // Tuple returning
   at ref string Program.RefMethod(in string value)+LocalFuncRefReturn()                 // ref return local func
   at int Program.RefMethod(in string value)+LocalFuncParam(string val)                  // local function
   at string Program.RefMethod(in string value)                                          // in param (readonly ref)    
   at (string val, bool) static Program()+(string s, bool b)=>{}                         // tuple return static lambda
   at void static Program()+(string s, bool b)=>{}                                       // void static lambda
   at void Program.Start((string val, bool) param)                                       // Resolved tuple param
   at void Program.Start((string val, bool) param)+LocalFunc1(long l)                    // void local function 
   at bool Program.Start((string val, bool) param)+LocalFunc2(bool b1, bool b2)          // bool return local function 
   at string Program.Start()                                                              
   at void Program()+()=>{}                                                              // ctor defined lambda  
   at void Program(Action action)+(object state)=>{}                                     // ctor defined lambda 
   at void Program.RunAction(Action<object> lambda, object state)                         
   at new Program(Action action)                                                         // constructor 
   at new Program()                                                                      // constructor 
   at void Program.Main(String[] args)                                                    

Calling .ToString() on the same exception would produce the following output

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.ThrowHelper.ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion() // ? low value
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()                         
   at Program.<Iterator>d__3.MoveNext()                                                   // which enumerator?
   at System.Linq.Enumerable.SelectEnumerableIterator`2.MoveNext()                        // which enumerator?
   at System.String.Join(String separator, IEnumerable`1 values)                          
   at Program.GenericClass`1.GenericMethod[TSubType](TSubType& value)                     
   at Program.<MethodAsync>d__4.MoveNext()                                                // which async overload?
--- End of stack trace from previous location where exception was thrown ---              // ? no value
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()                      // ? no value
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) // ? no value
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()                           // ? no value
   at Program.<MethodAsync>d__5`1.MoveNext()                                              // which async overload?
--- End of stack trace from previous location where exception was thrown ---              // ? no value
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()                      // ? no value
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) // ? no value
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()                           // ? no value
   at Program.<>c__DisplayClass8_0.<Method>b__0()                                         //  ¯\_(ツ)_/¯
   at Program.<>c__DisplayClass8_0.<Method>b__1()                                         //  ¯\_(ツ)_/¯
   at Program.RunLambda(Func`1 lambda) 
   at Program.Method(String value)
   at Program.<RefMethod>g__LocalFuncRefReturn|10_1(<>c__DisplayClass10_0& )              // local function
   at Program.<RefMethod>g__LocalFuncParam|10_0(String val, <>c__DisplayClass10_0& )      // local function
   at Program.RefMethod(String value)
   at Program.<>c.<.cctor>b__18_1(String s, Boolean b)                                    //  ¯\_(ツ)_/¯
   at Program.<>c.<.cctor>b__18_0(String s, Boolean b)                                    //  ¯\_(ツ)_/¯
   at Program.Start(ValueTuple`2 param)                                                   // Tuple param?
   at Program.<Start>g__LocalFunc1|11_0(Int64 l)                                          // local function
   at Program.<Start>g__LocalFunc2|11_1(Boolean b1, Boolean b2)                           // local function
   at Program.Start()
   at Program.<>c.<.ctor>b__1_0()                                                         //  ¯\_(ツ)_/¯
   at Program.<>c__DisplayClass2_0.<.ctor>b__0(Object state)                              //  ¯\_(ツ)_/¯
   at Program.RunAction(Action`1 lambda, Object state)
   at Program..ctor(Action action)                                                        // constructor
   at Program..ctor()                                                                     // constructor
   at Program.Main(String[] args)

Which is far less helpful, and close to jibberish in places

Problems with current stack traces:

  • constructors

    Does not match code, output as .ctor and .cctor

  • parameters

    Do not specify qualifier ref, out or in

  • iterators

    Cannot determine overload <Iterator>d__3.MoveNext() rather than Iterator(int startAt)+MoveNext()

  • Linq

    Cannot determine overload

    Linq.Enumerable.SelectEnumerableIterator``2.MoveNext()

    rather than

    Linq.Enumerable+SelectEnumerableIterator<TSource, TResult>.MoveNext()

  • async

    Cannot determine overload and no modifier such as async

    <MethodAsync>d__5``1.MoveNext()

    rather than

    async Task<string> Program.MethodAsync(int value)

    Noise!

    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
    at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) 
    at System.Runtime.CompilerServices.TaskAwaiter.GetResult() 
    
  • lambdas

    Mostly jibberish <>c__DisplayClass2_0.<.ctor>b__0(Object state) with a suggestion of where they are declared but no hint if there are multiple overloads of the method.

  • local functions

    Mostly jibberish <RefMethod>g__LocalFuncParam|10_0(String val, <>c__DisplayClass10_0& ) with a suggestion of where they are declared but no hint if there are multiple overloads of the method.

  • generic parameters

    Not resolved, only an indication of the number RunLambda(Func``1 lambda) rather than RunLambda(Func<string> lambda)

  • value tuples

    Do not match code, output as ValueTuple``2 param rather than (string val, bool) param

  • primitive types

    Do not match code, output as Int64, Boolean, String rather than long, bool, string

  • return types

    Skipped entirely from method signature

Benchmarks

To run benchmarks from the repository root:

dotnet run -p .\test\Ben.Demystifier.Benchmarks\ -c Release -f netcoreapp2.0 All

Note: we're only kicking off via netcoreapp2.0, benchmarks will run for all configured platforms like net462.