New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improved formatting for async stack traces #2813

Closed
aelij opened this Issue Jan 22, 2016 · 19 comments

Comments

Projects
None yet
6 participants
@aelij
Copy link

aelij commented Jan 22, 2016

Currently, for a simple invocation of async M1 -> async M2 -> M3 we will produce the following stack trace string:

System.InvalidOperationException: X
   at AsyncStackTrace.Program.M3() in ...\AsyncStackTrace\Program.cs:line 49
   at AsyncStackTrace.Program.<M2>d__2`1.MoveNext() in ...\AsyncStackTrace\Program.cs:line 37
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at AsyncStackTrace.Program.<M1>d__1.MoveNext() in ...\AsyncStackTrace\Program.cs:line 24

Observations:

  • All the frames from awaiters are redundant and do not really add much information.
  • The "end of stack trace from previous location" text, caused by ExceptionDispatchInfo can also be omitted.
  • Async method name can be inferred from its generated class name.

I'm suggesting to have the option to replace it with a more concise, readable version:

System.InvalidOperationException: X
   at AsyncStackTrace.Program.M3() in ...\AsyncStackTrace\Program.cs:line 49
   at async AsyncStackTrace.Program.M2[TValue](?) in ...\AsyncStackTrace\Program.cs:line 37
   at async AsyncStackTrace.Program.M1(?) in ...\AsyncStackTrace\Program.cs:line 24

The ? is here to remind the developer we can't extract the original method's parameters.

This can be easily implemented by adding an option to the StackTrace.ToString() method. A sample implementation is in this gist:
https://gist.github.com/aelij/7b9c259fb94d569076e3

Open issues:

  • Dealing with remote stack traces (RealProxy, WCF).

cc: @stephentoub

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Jan 26, 2016

@aelij Thanks for writing this up!

Let me know your thoughts on this. I feel like the right approach at first would be to create a higher level library that handles this formatting, and then users can opt-in to the new formatting by calling some API such as:
AsyncStackTrace.Format(StackTrace)

This API could even be in a NuGet package you create, and if other developers are interested in similar functionality we can point them at it. I believe the ASP.NET folks were interested.

In my mind it would take the same amount of effort for users to change to use StackTrace.ToString("NewThing") as it is to call a new API entirely. The benefit of having a new API is that it doesn't couple the formatting to the low level runtime components. Once we couple it all applications have to pay for this code size regardless of whether they use it, and it will become difficult to make further adjustments. For example maybe a 2nd group of users will decide they want the formatting to be a little different, or they care about abstracting away a different technical area such as WCF or RealProxy as you mentioned. I wouldn't want the relatively low level StackTrace API to become a dumping ground for all higher level abstractions to insert their private implementation details, though I agree that certain abstractions, such as async, might have far more merit than others.

If we did go the route of getting something added directly to StackTrace I'd be attempted to either:

  1. make it an extensible system where any number of modifications can be plugged in on demand. Async could be one such modification.
  2. Increase confidence that a particular format for a particular abstractions is worth hard coding into the lower level by getting feedback from developers who already use the exact same technique from a higher level library.

What do you think?
Thanks!
-Noah

@aelij

This comment has been minimized.

Copy link

aelij commented Jan 26, 2016

Hi Noah,

What you say does make sense, but -

  • Async is now so prevalent that I do think it has a merit to be included in the core framework
  • Visual Studio is already doing something similar when presenting async call stacks
  • The code size changes are very small
  • It would be next to impossible to make this work for RealProxy exceptions (on the desktop framework) without framework support

Making it extensible does sound like a neat idea. As long as it doesn't have serious perf implications.

@aelij

This comment has been minimized.

Copy link

aelij commented Jan 26, 2016

Just to get a feeling of what motivated this, take a look at the following (real! just a few names mangled) stack trace, which is a Web API calling a Service Fabric micro services chain, all with async of course. It's very difficult to grok; there so much noise:

System.AggregateException: One or more errors occurred. ---> System.ArgumentException: Something bad happened
   at MyServer.MyService.<MyMethod>d__21.MoveNext() in C:\Source\Server\Services.X\X.cs:line 2
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Runtime.ServiceMethodDispatcherBase.<>c__DisplayClass4`1.<ContinueWithResult>b__3(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Runtime.ServiceMethodDispatcherBase.<Microsoft.ServiceFabric.Services.Remoting.Runtime.IServiceMethodDispatcher.DispatchAsync>b__1(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Runtime.ServiceRemotingDispatcher.<>c__DisplayClass1.<DefaultDispatch>b__0(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MyServer.Hosting.Wcf.WcfServiceRemotingListener.WcfRemotingService.<RequestResponseAsync>d__6.MoveNext() in C:\Source\Server\Z.cs:line 7
   --- End of inner exception stack trace ---
   at Microsoft.ServiceFabric.Services.Communication.Client.ServicePartitionClient`1.<InvokeWithRetryAsync>d__7`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Client.ServiceProxy.<InvokeAsync>d__2.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Client.ServiceProxy.<ContinueWithResult>d__a`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MyServer.WebApi.Controller.<DoSomething>d__17.MoveNext() in C:\Source\Server\Y.cs:line 3
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Threading.Tasks.TaskHelpersExtensions.<CastToObject>d__3`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__0.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__5.MoveNext()
---> (Inner Exception #0) System.ArgumentException: Something bad happened
   at MyServer.MyService.<DoSomething>d__21.MoveNext() in C:\Source\Server\K.cs:line 4
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Runtime.ServiceMethodDispatcherBase.<>c__DisplayClass4`1.<ContinueWithResult>b__3(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Runtime.ServiceMethodDispatcherBase.<Microsoft.ServiceFabric.Services.Remoting.Runtime.IServiceMethodDispatcher.DispatchAsync>b__1(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.ServiceFabric.Services.Remoting.Runtime.ServiceRemotingDispatcher.<>c__DisplayClass1.<DefaultDispatch>b__0(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MyServer.Hosting.Wcf.WcfServiceRemotingListener.WcfRemotingService.<RequestResponseAsync>d__6.MoveNext() in C:\Source\Server\Z.cs:line 7
@aelij

This comment has been minimized.

Copy link

aelij commented Jan 26, 2016

Another thing to consider: have the compiler emit an attribute with the original method's signature, so we wouldn't have to parse it. For example:

[AsyncMethodSignature("M1(int)")]
class <M1>d__1 : IAsyncStateMachine { ... }
@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Jan 26, 2016

Async is now so prevalent that I do think it has merit to be included in the core framework

I agree on the prevalence. That part I'm not so clear on is how much are .Net users gaining if the API is in the core framework vs. in a NuGet package they could easily add to any project. To my mind the major benefit would be if they didn't have to change their code because StackTrace.ToString() just started giving a better result by default (that does nastly things for back-compat so I am not seriously suggesting it). However if the alternative is StackTrace.ToString("NEW") then developers will have to change their code no matter what so the benefit seems much lower? There are also downsides to being in the core framework such as once stuff gets in there its very hard to change. On Desktop StackTrace.ToString() is implemented in mscorlib, so if you wanted to use the new formatting capability on .Net 4.5 you would be out of luck whereas when it is distributed in a separate NuGet package there is no issue. Being in the core framework doesn't necessarily mean you get the broadest reach - sometimes its better for important APIs not to be in the core framework.

Visual Studio is already doing something similar when presenting async call stacks

Agreed, though VS also changes callstacks in many other ways, and they continue to adjust the formatting over time in response to feedback and user studies. I see little reason to believe they will stop innovating in this space which suggests that many developers might appreciate the continuing stream of innovations in a more rapidly changing library vs a core framework API that has significant back-compat expectations.

The code changes are very small

We may have different definitions of very small : ) However size probably isn't the top concern at the moment relative to layering, stability, and update frequency so we can let this part lie.

It would be next to impossible to make this work for RealProxy exceptions (on the desktop framework) without framework support

This is probably the best reason so far to put something directly into the framework, though it may only argue for adding specific APIs that expose the necessary data vs. adding the updated formatters. If you wanted to try moving this RealProxy part forward the next step is probably to specify exactly which additional data you would need to do the formatting you envision, and propose an API that gets that data exposed.

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Jan 26, 2016

To be fair I should also mention on desktop framework, it may be much harder to get a feature added than on coreclr. Better stack traces for RealProxy is not something I've observed much feedback about in the community. If you think lots of developers that would rally behind the request UserVoice is a great way to let people vote up the feature.

@aelij

This comment has been minimized.

Copy link

aelij commented Jan 26, 2016

Okay, you've somewhat convinced me :) I'll create a NuGet package for this.

BTW, my original thought was to also include a setting for the default stack trace format, so recompilation would not be necessary. That way, StackTrace.ToString() and Exception.ToString() could benefit from it. Incidentally, StackTrace already has a TraceFormat enum. We could've just added another option to it.

To be fair I should also mention on desktop framework, it may be much harder to get a feature added than on coreclr.

Didn't I read somewhere that you'll be bringing the new stuff from coreclr to the desktop eventually?

@RichiCoder1

This comment has been minimized.

Copy link

RichiCoder1 commented Jan 26, 2016

Let me know if you need any help with that package. Very interested in this myself. If the package gets popular enough, too, it would provide incentive to bring it into core.

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Jan 27, 2016

Didn't I read somewhere that you'll be bringing the new stuff from coreclr to the desktop eventually?

Its possible, I might be the one out of the loop : )

@aelij

This comment has been minimized.

Copy link

aelij commented Feb 3, 2016

@noahfalk, I've started working on the library, and I realized something - there's one more very compelling case for including it in the core library (with the option to make it the default, as I mentioned above) - serialization.

When an exception is serialized and deserialized, its stack trace is saved to the _stackTraceString field, and there is no way to produce the original stack using the StackTrace class. Using an external library to format the stack trace would require "preparing" the exception before it gets serialized (e.g. by saving the formatted stack trace in the Data dictionary property). It also has the disadvantage of including both formatted strings in the serialized data.

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Feb 4, 2016

@aelij Hmm, perhaps adding an extensibility point would be the right way to go? The first idea that comes to mind would be something like:

   class StackTrace
   {
        public static Func<StackTrace, string> StackTraceFormatter { get; set; }
   }

Imagine this gets used for all places the runtime formats a stack trace (lots of hand waving about details). This would let a 3rd party library swap out the default formatting logic with something else, while still forcing apps to explicitly opt-in by changing the property.

There would certainly be other complexities such as figuring out how this interacts with the existing format enumeration, and ensuring that it doesn't violate any security rules. Last I heard we were deprecating most (all?) of our runtime security sandboxing, but I still see many references to file permissions and making sure PII information like file paths doesn't leak to untrusted code.
Adding a few other people to get thoughts:

@weshaggard @stephentoub @davidfowl

@aelij

This comment has been minimized.

Copy link

aelij commented Feb 4, 2016

I like it!

Regarding file paths, there's an option to strip them, but from what I can tell it's not used in any managed code path. The current stripping method (StripFileInfo, implemented in native code) uses text manipulation (removes everything after the last right bracket) - but it returns null if the virtual StackTrace property was overridden for remote stack traces (cross app-domain and real proxy; not relevant for coreclr as far as I know).

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Feb 4, 2016

Cool : )

If you want to drive this framework part of the work forward, the workflow mentioned here is probably what you want to follow: https://github.com/dotnet/coreclr/blob/master/Documentation/project-docs/contributing-workflow.md

I would warn that this feature doesn't appear to align with any of the major priorities: https://github.com/dotnet/coreclr/blob/master/Documentation/project-docs/project-priorities.md
I'm happy to offer my feedback, but other people might be more focused on tasks related to those priorities so if they aren't being responsive, that's probably why.

HTH,
-Noah

@ayende

This comment has been minimized.

Copy link
Contributor

ayende commented Feb 5, 2016

👍

This is really important on the coreclr, where the StackTrace on the exception is just a string.

@aelij

This comment has been minimized.

Copy link

aelij commented Feb 19, 2016

I've published the package:
https://github.com/aelij/AsyncFriendlyStackTrace

The README also lists a few compelling examples.

Let me know what you think.

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Feb 19, 2016

👍 I'm hoping we might get @davidfowl to take a look, seeing how he opened this other very similar issue dotnet/corefx#1370 and in theory he wants something like this ; )

@ayende

This comment has been minimized.

Copy link
Contributor

ayende commented Feb 19, 2016

Would this work on the CoreCLR?

*Hibernating Rhinos Ltd *

Oren Eini* l CEO l *Mobile: + 972-52-548-6969

Office: +972-4-622-7811 *l *Fax: +972-153-4-622-7811

On Fri, Feb 19, 2016 at 10:46 AM, Eli Arbel notifications@github.com
wrote:

I've published the package:
https://github.com/aelij/AsyncFriendlyStackTrace

The README also lists a few compelling examples.

Let me know what you think.


Reply to this email directly or view it on GitHub
#2813 (comment).

@aelij

This comment has been minimized.

Copy link

aelij commented Feb 19, 2016

Yes, it's a multi-target package. Check out the NuGet page:
https://www.nuget.org/packages/AsyncFriendlyStackTrace/

@karelz

This comment has been minimized.

Copy link
Member

karelz commented Oct 13, 2017

This feels like duplicate of dotnet/corefx#1370, closing.

I think it is worthwhile to track the request in just one issue.
If it is subtly different from #1370, please let me know.

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