Skip to content
This repository was archived by the owner on Jan 23, 2023. It is now read-only.

More readable stack traces (StackTrace method opt-out)#14608

Closed
benaadams wants to merge 15 commits intodotnet:masterfrom
benaadams:stacktracehidden
Closed

More readable stack traces (StackTrace method opt-out)#14608
benaadams wants to merge 15 commits intodotnet:masterfrom
benaadams:stacktracehidden

Conversation

@benaadams
Copy link
Member

@benaadams benaadams commented Oct 20, 2017

Follow on from #14564 but also works for Debug build and doesn't rely on Jit behavior

Currently from looking at a stack trace there's a lot of noise; but perhaps more importantly there isn't enough detail to tell what overloads of a method were called for async and iterators due to the name mangling prior to MoveNext().

This PR seeks to address both these issues; so that using the stack trace output is a more productive experience; whether trying to identify causes from logs and what code to look at, or just to not be daunting to new developers. (Also provide opt-outs to previous behavior and allow future extensibility).

It adds the following internal items to System.Diagnotsics (will seek api review to make public)

[Flags]
internal enum StackTraceFormattingOptions
{
    None                                 = 0,
    ExcludeStackTraceHiddenAttribute     = 1 << 0,
    ExcludeDispatchBoundaries            = 1 << 1,
    ExcludeInnerExceptionBoundaries      = 1 << 2,
    ResolveAsyncMethods                  = 1 << 3,
    ResolveIteratorMethods               = 1 << 4,
}

public partial class StackTrace
{
    internal static StackTraceFormattingOptions FormattingOptions { get; set; } 
            = StackTraceFormattingOptions.ExcludeStackTraceHiddenAttribute
              | StackTraceFormattingOptions.ExcludeDispatchBoundaries
              | StackTraceFormattingOptions.ResolveAsyncMethods
              | StackTraceFormattingOptions.ResolveIteratorMethods;
}

The default formatting is
ExcludeStackTraceHiddenAttribute | ExcludeDispatchBoundaries | ResolveAsyncMethods | ResolveIteratorMethods.

Adding [StackTraceHidden] to a method will drop it from the StackTrace and adding it to the class/struct will drop all of its methods from the trace.

For async methods and users of ExceptionDispatchInfo

ExcludeStackTraceHiddenAttribute

Outputs

   at Program.<DelayedAsync>d__2.MoveNext()

Instead of

   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() 
   at Program.<DelayedAsync>d__2.MoveNext()

For ThrowHelper methods

Outputs

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()

Instead of

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.ThrowHelper.ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion()
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()

So they act as in-place throws

ResolveIteratorMethods

Outputs

at System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`3 predicate)
at Program.Iterator(Int64 count, Int32 value) 

Instead of

at System.Linq.Enumerable.<SkipWhileIterator>d__179`1.MoveNext()
at Program.<Iterator>d__4.MoveNext() 

ResolveAsyncMethods

Outputs

at Program.ValueTaskAsync(String name) 
at Program.TaskTAsync(Int32 count) 

Instead of

at Program.<ValueTaskAsync>d__9.MoveNext() 
at Program.<TaskTAsync>d__11.MoveNext() 

ExcludeDispatchBoundaries drops

--- End of stack trace from previous location where exception was thrown ---

ExcludeInnerExceptionBoundaries drops (included by default)

   --- End of inner exception stack trace ---

Resolves: https://github.com/dotnet/corefx/issues/24627

@stephentoub @noahfalk PTAL

@benaadams
Copy link
Member Author

benaadams commented Oct 20, 2017

Using settings

StackTraceFormattingOptions.ExcludeStackTraceHiddenAttribute | 
StackTraceFormattingOptions.ExcludeDispatchBoundaries |
StackTraceFormattingOptions.ExcludeInnerExceptionBoundaries |
StackTraceFormattingOptions.ResolveAsyncMethods |
StackTraceFormattingOptions.ResolveIteratorMethods

The output is

System.Exception: Inner1 ---> System.Exception: Inner2 ---> System.Exception: Inner3 ---> System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at Program.FirstException(Int32 value, Int32 index)
   at Program.<>c.<LinqIteration>b__3_0(Int32 x, Int32 i) 
   at System.Linq.Enumerable.SkipWhileIterator[TSource](IEnumerable`1 source, Func`3 predicate)
   at System.Collections.Generic.LargeArrayBuilder`1.AddRange(IEnumerable`1 items)
   at System.Collections.Generic.EnumerableHelpers.ToArray[T](IEnumerable`1 source)
   at Program.LinqIteration(Int32 count)
   at Program.Iterator(Int64 count, Int32 value)
   at Program.InnerException3() 
   at Program.InnerException3() 
   at Program.InnerType`1.InnerException2(Int32 count)
   at Program.InnerType`1.InnerException2(Int32 count)
   at Program.InnerException1[T](Int32 count)
   at Program.InnerException1[T](Int32 count) 
   at Program.NonAsyncValueTask(Int32 count, String name) 
   at Program.ValueTaskAsync(String name) 
   at Program.TaskTAsync(Int32 count) 
   at Program.MethodAsync(Int32 count) 
   at Program.ConfiguredAsync(Int32 count) 
   at Program.MethodAsync(Int32 count) 
   at Program.ConfiguredAsync(Int32 count) 
   at Program.MethodAsync(Int32 count) 
   at Program.Main(String[] args) 

Rather than

System.Exception: Inner1 ---> System.Exception: Inner2 ---> System.Exception: Inner3 ---> System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.ThrowHelper.ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion()
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at Program.FirstException(Int32 value, Int32 index)
   at Program.<>c.<LinqIteration>b__3_0(Int32 x, Int32 i)
   at System.Linq.Enumerable.<SkipWhileIterator>d__179`1.MoveNext()
   at System.Collections.Generic.LargeArrayBuilder`1.AddRange(IEnumerable`1 items)
   at System.Collections.Generic.EnumerableHelpers.ToArray[T](IEnumerable`1 source)
   at Program.LinqIteration(Int32 count) 
   at Program.<Iterator>d__4.MoveNext()
   at Program.InnerException3()
   --- End of inner exception stack trace ---
   at Program.InnerException3()
   at Program.InnerType`1.InnerException2(Int32 count)
   --- End of inner exception stack trace ---
   at Program.InnerType`1.InnerException2(Int32 count)
   at Program.InnerException1[T](Int32 count)
   --- End of inner exception stack trace ---
   at Program.InnerException1[T](Int32 count)
   at Program.NonAsyncValueTask(Int32 count, String name)
   at Program.<ValueTaskAsync>d__9.MoveNext()
--- 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`1.GetResult() 
   at System.Runtime.CompilerServices.ValueTaskAwaiter`1.GetResult()
   at Program.<TaskTAsync>d__11.MoveNext()
--- 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`1.GetResult() 
   at Program.<MethodAsync>d__14.MoveNext()
--- 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.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult() 
   at Program.<ConfiguredAsync>d__13.MoveNext()
--- 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() 
   at Program.<MethodAsync>d__14.MoveNext()
--- 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.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult() 
   at Program.<ConfiguredAsync>d__13.MoveNext()
--- 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() 
   at Program.<MethodAsync>d__14.MoveNext()
--- 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() 
   at Program.<Main>d__0.MoveNext()

For program in #14608 (comment)

/// <exception cref="System.NullReferenceException">The awaiter was not properly initialized.</exception>
/// <exception cref="System.Threading.Tasks.TaskCanceledException">The task was canceled.</exception>
/// <exception cref="System.Exception">The task completed in a Faulted state.</exception>
[StackTraceHidden]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added and moved Attribute to shared partition

@stephentoub
Copy link
Member

If @noahfalk is ok with this approach and there aren't other unexpected consequences of leaving things out of the StackTrace (does this only affect the string-rendered stack trace, or would it also affect what the VS debugger shows or anything like that?), then I'm fine with it, too, and prefer it over the more invasive changes in the previous attempt.

@benaadams
Copy link
Member Author

does this only affect the string-rendered stack trace

It only effects the .ToString() and .ToString(TraceFormat traceFormat) methods; they methods show up in VS callstack window.

vs Callstack

@benaadams benaadams changed the title Add StackTraceHidden Attribute Add StackTraceHidden Attribute (Readable async stack traces) Oct 20, 2017
@noahfalk
Copy link
Member

@gregg-miskelly @tmat @weshaggard @terrajobst
Thanks Ben! A few questions to get additional feedback:

Back compat/opt-out - We tell people not to depend on stacktrace format and most people probably don't, but its certainly possible that apps have taken these dependencies. Some (probably a very small percentage) may also dislike the alternate frame-hiding policy. Do we have a way to flight BCL changes that deliberately change user visible behavior to mitigate the risks? Any design conventions for how to expose an opt-out to users that are adversely affected?

VS convergence - This change effectively creates a new JMC-style filtering policy that is orthogonal to all the policies in VS. I'm wondering if it would be better to use the pre-existing DebuggerHidden attribute. DebuggerHidden implies that the method won't show up in a VS stacktrace either. I think of this as "if most users don't want to see the method in their exception stack traces, why would they want to see it in VS? and vice versa." Granted this may make it worse for the small percentage of users who did want to see these methods in their stack trace and now we also are hiding them in the debugger. I have a feeling @stephentoub might be in that small group because as the maintainer of the code he would probably sad if the debugger hides it from him. I'm hoping I can either get Stephen to make a sacrifice on that one or maybe @gregg-miskelly can help us add a similar opt-out for DebuggerHidden to VS or you guys can convince me this isn't a good idea? I doubt the VS opt-out would need to be anything flashy, even a simple reg key that a handful of BCL devs could set would likely go a long way to making DebuggerHidden more palatable.

Thoughts?


internal static int CalculateFramesToSkip(StackFrameHelper StackF, int iNumFrames)
{
const string DiagnosticsPackageName = nameof(System.Diagnostics);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe this nameof will just return "Diagnostics"

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

StackFrame sf = GetFrame(iFrameIndex);
MethodBase mb = sf.GetMethod();
if (mb != null)
if (mb != null && !(mb.IsDefined(typeof(StackTraceHiddenAttribute)) || mb.DeclaringType.IsDefined(typeof(StackTraceHiddenAttribute))))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you factor out the new part of the conditional into a little helper method and make it clear with the naming/comments that this is our filtering policy? I suspect there may be some continued tweaking over time and I want to keep the policy choice isolated from the code here that applies the policy.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@tmat
Copy link
Member

tmat commented Oct 20, 2017

@benaadams Perhaps we could use the existing DebuggerNonUserCodeAttribute instead. I think the semantics of this attribute in VS is the same as DebuggerHiddenAttribute when Just My Code is on otherwise it's ignored. We could assume that the CLR stack trace API always has JMC on, or perhaps add a new constructor that takes the JMC flag. Or perhaps better, if we added the new constructor and by default have JMC off then we could make this 100% backward compatible. The app would need to opt-in when displaying stack traces. If we think that most apps will be ok with the new behavior we could also make it opt-out via a compat switch in App.config.

@jkotas
Copy link
Member

jkotas commented Oct 20, 2017

Earlier versions of .NET Native did not include the names of the framework internal methods in the textual stacktraces (pretty similar to what you get with JMC in VS). We received a strong feedback that it makes problems hard to diagnose. We have done work to add the names for most internal methods back in the stacktraces in .NET Native based on this feedback.

@tmat
Copy link
Member

tmat commented Oct 20, 2017

@jkotas That would suggest that an opt-in flag in StackTrace API would be preferable. Depending on context -- diagnostic logging vs user-friendly stack traces, one could set the JMC value. And the default would be as it is today.

@benaadams
Copy link
Member Author

DebuggerNonUserCodeAttribute only seems to be used by System.Xml.Xsl.IlGen so is ok from not being a wide net,

However, for this usage it changes the behavior of the Awaiters in the debugger (as they don't currently have any of these attributes)

The common language runtime attaches no semantics to this attribute. It is provided for use by source code debuggers. For example, in Visual Studio 2005, the debugger does not display an element with this attribute in the debugger window, does not stop in a method with this attribute, and does not allow a breakpoint to be set in the method.

The debugger behavior when the DebuggerNonUserCodeAttribute is present is similar to using a combination of the DebuggerHiddenAttribute attribute, which hides the code from the debugger, and the DebuggerStepThroughAttribute attribute, which tells the debugger to step through, rather than into, the code it is applied to.

Is this ok?

@benaadams
Copy link
Member Author

Back compat/opt-out - We tell people not to depend on stacktrace format and most people probably don't, but its certainly possible that apps have taken these dependencies.

Then they are probably already in trouble as the methods appear and disappear depending on whether they get inlined or not, ExceptionDispatchInfo.Throw() is a new entrant; GetResult and ValidateEnd only sometimes appear in traces etc

I think removing the boundaries would be an issue

--- End of stack trace from previous location where exception was thrown ---

Though I'd like to get rid of those too :)

Opt-out to return the extra; and extra opt-in to remove the boundaries?

That would suggest that an opt-in flag in StackTrace API would be preferable. ... And the default would be as it is today.

I don't think opt-in is good; most people are overwhelmed by the extra entries (from new user, to seasoned dev) and the people that will opt-in (and know about opt-in) are the same people who have already written tools to eat the stack trace and throw away the additional entries anyway like @NickCraver https://github.com/dotnet/corefx/issues/24627#issuecomment-336327971

We've got the same issue, not ideal (since this should be done on generation ideally), but we handle text-based versions after the fact like this:


Current code (again, string-based, but gives an idea): https://github.com/NickCraver/StackExchange.Exceptional/blob/master/src/StackExchange.Exceptional.Shared/ExceptionalUtils.StackTrace.cs

I'd love to see the framework do this much better. It's one of the big negatives to taking a codebase async.

@noahfalk
Copy link
Member

@jkotas - I wasn't clear if your comment was suggesting a specific implementation choice suggested here was bad or a broader statement that any policy that eliminates frames is bad, or simply to provide a good counter example to my theory that users have the same expections for callstacks in a debugger as they do for callstacks in the exception stacktrace?

@benaadams

However, for this usage it changes the behavior of the Awaiters in the debugger (as they don't currently have any of these attributes)

What change in behavior did you observe with the NonUserCodeAttribute? I'm surprised it made a difference given that VS winds up treating all BCL code as non-user by default (because it is compiled in Release). If you happened to be building your own BCL libraries in debug and testing VS on that then you've accidentally sent yourself down a different path than the standard customer sees.

@tmat - thinking about it NonUser does feel a better expression of this than DebuggerHidden and it already has an easy opt-out in VS, turn JMC off. I do want to sure we aren't inadvertently degrading some other debugger behavior though.

I agree with @benaadams that on-by-default is where most of the value is, despite making things harder for us.

@benaadams
Copy link
Member Author

What change in behavior did you observe with the NonUserCodeAttribute?

Actually nothing when JMC was off; it only skipped the methods when it was on - so that's probably ok :)

@benaadams
Copy link
Member Author

@dotnet-bot test OSX10.12 x64 Checked Build and Test

@benaadams benaadams changed the title Add StackTraceHidden Attribute (Readable async stack traces) Readable async stack traces Oct 20, 2017
@benaadams benaadams changed the title Readable async stack traces Readable async stack traces (StackTrace method opt-out) Oct 20, 2017
@benaadams
Copy link
Member Author

Upping the ante with last change 48ae315 marking ThrowHelper as DebuggerNonUserCode

So

public static void Main(string[] args)
{
    var list = new List<int> { 0, 1, 2, 3 };
    try
    {
        foreach (var item in list)
        {
            list.Add(item);
        }
    }
    catch (Exception e)
    {
        Console.WriteLine(e);
    }
}

Outputs

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at Program.Main(String[] args)

Instead of

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.ThrowHelper.ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion()
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at Program.Main(String[] args)

So the ThrowHelper presents as an in-place throw?

@benaadams benaadams changed the title Readable async stack traces (StackTrace method opt-out) More readable stack traces (StackTrace method opt-out) Oct 20, 2017
@aelij
Copy link

aelij commented Oct 21, 2017

Please also port this to the desktop framework :)

@benaadams
Copy link
Member Author

RemapAsyncStateMachineMethodNames

Think can go one better than just resolving the names; and add all the parameters back too.

Changed flags to StackTraceFormattingOptions

Reduced allocations by plumbing StringBuilder through rather than sting concats

Added options ResolveAsyncMethods & ResolveIteratorMethods

@benaadams
Copy link
Member Author

benaadams commented Oct 21, 2017

*Moved Trace to second post #14608 (comment)

For program

public class Program
{
    public static async Task Main(string[] args)
    {
        Console.ReadLine();
        try
        {
            await MethodAsync(2);
        }
        catch (Exception e)
        {
            Console.WriteLine(e);
        }
    }

    static List<int> _list = new List<int> { 1, 2, 3 };

    private static bool FirstException(int value, int index)
    {
        foreach (var ii in _list)
        {
            _list.Add(ii - 1);
        }

        return true;
    }

    private static int LinqIteration(int count)
    {
        var sum = 0;
        var list = new List<int>{1,2,3};

        var data = list.SkipWhile((x, i) => FirstException(x, i)).ToArray();

        return data.Sum();
    }

    private static IEnumerable<int> Iterator(long count, int value)
    {
        yield return 1;
        yield return LinqIteration(2);
        yield return 3;
    }

    private static int InnerException3()
    {
        try
        {
            int val = 0;
            foreach (var i in Iterator(1L, 1))
            {
                val = i;
            }
            return val;
        }
        catch (Exception e)
        {
            throw new Exception("Inner3", e);
        }
    }

    struct InnerType<T>
    {
        public static int InnerException2(int count)
        {
            try
            {
                return InnerException3();
            }
            catch (Exception e)
            {
                throw new Exception("Inner2", e);
            }
        }
    }

    private static int InnerException1<T>(int count)
    {
        try
        {
            return InnerType<int>.InnerException2(count);
        }
        catch (Exception e)
        {
            throw new Exception("Inner1", e);
        }
    }

    private static ValueTask<int> NonAsyncValueTask(int count, string name)
    {
        return new ValueTask<int>(InnerException1<string>(count));
    }
    private static async ValueTask<int> ValueTaskAsync(string name)
    {
        return await NonAsyncValueTask(1, "");
    }
    private static async Task<int> TaskTAsync(long count)
    {
        return await ValueTaskAsync("");
    }
    private static async Task<int> TaskTAsync(int count)
    {
        return await ValueTaskAsync("");
    }
    private static async Task<int> TaskTAsync(long count, string name)
    {
        return await ValueTaskAsync("");
    }

    private static async Task ConfiguredAsync(int count)
    {
        await MethodAsync(count).ConfigureAwait(true);
    }

    private static async Task MethodAsync(int count)
    {
        if (count == 0)
        {
            await TaskTAsync(count);
        }
        else
        {
            await ConfiguredAsync(count - 1);
        }
    }
}

@benaadams
Copy link
Member Author

Added some Linq; only item I can see that's not sane is the lambda (also closures); might have missed some variants?

// Builds a readable representation of the stack trace, specifying
// the format for backwards compatibility.
internal String ToString(TraceFormat traceFormat)
{
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe use StringBuilderCache?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thought about that but StringBuilderCache allocates a new one if current is too small; and has a retained limit of 350 chars - and the stack traces are pretty big; so its either going to bloat the cache or always allocate anyway :-/

{
t = ResolveAsyncMethod(t, ref mb);
}
else if (FormattingOptions.HasFlag(StackTraceFormattingOptions.ResolveIteratorMethods) && typeof(IEnumerable).IsAssignableFrom(t))
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should check for IEnumerator instead (works if iterator returns IEnumerable or IEnumerator)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good tip

if (dt != null)
{
string fullName = t.FullName;
var start = fullName.LastIndexOf('<');
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note this assumes a C#-specific mangled name format. I've suggested in the past that the compiler should emit an attribute on the state machine that resolves the method (e.g. by including a signature string or at least a name).

Also, I think this is a non-negligible computation for a "nice to have" feature (getting the list of argument types): resolving multiple MemberInfos, allocating an array, allocating attributes...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note this assumes a C#-specific mangled name format.

Need to check the names used across the languges, worse case it doesn't look it up and leaves the name alone

The compiler should emit an attribute on the state machine that resolves the method

Would be useful

Also, I think this is a non-negligible computation for a "nice to have" feature

Its an opt-in; but without it and without line numbers it makes it hard to workout which of the overloads in the example program is being called if the name alone was cleaned

async Task<int> TaskTAsync(long count);
async Task<int> TaskTAsync(int count);
async Task<int> TaskTAsync(long count, string name);

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VB is something like

VB$StateMachine_3_BarAsync.MoveNext()

Copy link
Member Author

@benaadams benaadams Oct 21, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will do some throughput and allocation testing, but

Program.TaskTAsync(Int32 count)

Adds a lot of value over

Program.<TaskTAsync>d__11.MoveNext()

as you know which overload it was rather than having to manually track back via the il and try to eyeball it

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Full prettification has an insignificant cost compared to the exception handling

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

compiler should emit an attribute on the state machine that resolves the method

Is there a roslyn issue for this? Should I raise one?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please do not parse compiler generated names.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd recommend leaving the type and method name pretty-printing for a separate PR as it needs more design and discussion.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree with @tmat here. I'm behind the goal, but lets get the incremental progress on StackTraceHidden in the bag first. I imagine handling the compiler generated state machines in a robust way that doesn't tie the compiler's hands will take a little longer, using coordinated changes in both compiler and BCL.

@benaadams
Copy link
Member Author

benaadams commented Oct 21, 2017

For the program used as sample; the formatting has a pretty negligible effect on performance (the cost of the exceptions dominating) https://gist.github.com/benaadams/ebea3a947a57fe04e9fa0ee8bed48956

dotnet/master

Total Iters: 100,000 Elapsed: 00:00:53.7281390 Bytes Allocated: 1609294360
Ops Per Sec: 1,861.2 Elapsed Per Op: 00:00:00.0005373 Bytes Per Op: 16092

StackTraceFormattingOptions.None

Total Iters: 100,000 Elapsed: 00:00:54.3551537 Bytes Allocated: 1609283688
Ops Per Sec: 1,839.8 Elapsed Per Op: 00:00:00.0005436 Bytes Per Op: 16092

StackTraceFormattingOptions.ExcludeStackTraceHiddenAttribute

Total Iters: 100,000 Elapsed: 00:00:54.3543527 Bytes Allocated: 1609283688
Ops Per Sec: 1,839.8 Elapsed Per Op: 00:00:00.0005435 Bytes Per Op: 16092

StackTraceFormattingOptions.ExcludeStackTraceHiddenAttribute |
StackTraceFormattingOptions.ExcludeDispatchBoundaries |
StackTraceFormattingOptions.ExcludeInnerExceptionBoundaries |
StackTraceFormattingOptions.ResolveAsyncMethods |
StackTraceFormattingOptions.ResolveIteratorMethods

Total Iters: 100,000 Elapsed: 00:00:53.5627985 Bytes Allocated: 1609294360
Ops Per Sec: 1,867.0 Elapsed Per Op: 00:00:00.0005356 Bytes Per Op: 16092

@benaadams
Copy link
Member Author

With the rethrows from the async steps, its about 1M exceptions so 10k exceptions per second per core; which dwarfs any reflection

@benaadams
Copy link
Member Author

After looking at the perf, I think at least resolving the methods is probably a good default e.g.

ExcludeStackTraceHiddenAttribute | ResolveAsyncMethods | ResolveIteratorMethods

Then the stack trace matches the users code and the VS call stack window, which also has the methods resolved

VS stack

And it only shows the boundaries where it actually goes async; rather than just a transferring throw

VS async

However, I'm not sure how to detect that in the stack trace

internal enum StackTraceFormattingOptions
{
None = 0,
ExcludeStackTraceHiddenAttribute = 1 << 0,
Copy link
Member

@tmat tmat Oct 21, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ExcludeStackTraceHiddenAttribute [](start = 8, length = 32)

I like this enum. I wonder though, if we really need a new attribute now that we have an enum value specifying what should the behavior be. Having ExcludeNonUserCode flag and using DebuggerNonUserCodeAttribute would imo be better. Someone mentioned this attribute may already be used by some code generators. That's actually an argument for reusing the attribute. The intention of this attribute is to hide helpers that clutter debugging experience. To me that looks like what we are trying to do here as well. If we add a new attribute such generator will need to be updated to emit that attribute as well. Since we have a new flag that determines the stack formatting behavior it's not a breaking change to use the existing attribute.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that will work very well; also can tie up with the statemachine back pointers (and other generated code)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I could accept having an ExcludeNonUserCode flag on this enum, but at this point I have strong concerns about making it the default or considering it a replacement for the StackTraceHidden attribute. Pretty much same logic as above:
a) The msdn docs make it clear that DebuggerNonUserCode attribute doesn't have any runtime semantics. I don't want to make breaking changes on an unvalidated assumption that this is what users of that attribute would prefer.
b) Jan's example was excellent - .Net Native gave us a very strong example that users can be perfectly happy when VS hides something from them with JMC, but they complained extensively when the runtime hid that same thing from them in the exception callstack.

Its possible with a bunch of research about what code would be affected and talking to customers to see how they feel about those particular classes of methods we could ameliorate those concerns - but it strikes me as a lot of work and a lot of risk for a relatively small potential upside.

I still think we're better off sticking to the original ExcludeStackTraceHiddenAttribute and not even adding the ExcludeNonUserCodeAttribute until we've got a concrete customer pointing at a specific use case where the ability to customize that would help them.

Copy link
Member

@tmat tmat Oct 22, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

strong concerns about making it the default

I didn't mean it to be the default. On contrary. We should keep the default behavior as is. Having an option to treat DebuggerNonUserCode differently in StackTrace is not a breaking change. We can document that this flag exists in the attribute doc page.

If it is not a default and the code that displays the stack trace needs to pass in a new flag then (and only then) I believe adding a new attribute is not useful. It'd just add more complexity.

Copy link
Member

@tmat tmat left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🕐

// There is no good reason for the methods of this class to be virtual.
public class StackTrace
{
internal static StackTraceFormattingOptions FormattingOptions { get; set; }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If this is the proposed opt-out mechanism, presumably it needs to be public

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Its private public, can switch it off with reflection 😉

Will submit a corefx design for review when have agreed upon approach - though think we are close.

None = 0,
ExcludeStackTraceHiddenAttribute = 1 << 0,
ExcludeDispatchBoundaries = 1 << 1,
ExcludeInnerExceptionBoundaries = 1 << 2,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Concatenating across inner exceptions feels like another one that we should segregate out of this PR and bring up separately. It doesn't seem unreasonable as something people would want, but I don't feel I've seen much feedback on it either way. I'd rather not lump it with the async stuff where we have seen significant feedback already.

Copy link
Member

@noahfalk noahfalk left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm concerned we're trying to do too much in this one PR. I think we should segregate out the inner exception change until we've got reasonable feedback that justify people explicitly want that part. I also think we should segregate out the state machines and iterators to have a more collaborative design with the Roslyn team. Parsing method names is a brittle solution that ties the compiler's hands.

@jkotas
Copy link
Member

jkotas commented Oct 22, 2017

I'm concerned we're trying to do too much in this one PR

Agree. The delta at 123b932 looked like a pretty reasonable step to me. I would recommend going back to that point for this PR.

@benaadams
Copy link
Member Author

Will open new PR as I want to keep; the comments, but also squash

@benaadams
Copy link
Member Author

PR #14650

@benaadams
Copy link
Member Author

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

9 participants