Runtime: Fix Task Library Async Causality Stack Reconstruction

[vancem]

In synchronous code, a stack trace is a super-powerful way of describing 'where' you are in a program in a very useful way. We want this ability for asynchronous code as well. However this is not trivial because threads (and therefore their stacks) are constantly being reused. However the concept that one method 'calls' (more generally 'causes') another method to do something (its callee), is still valid

We have events (Scheduled, Begin, End), that fire when tasks are used for concurrency, and other events (WaitBegin and WaitEnd), that are used when C# 'await' routines are used. We also have logic in the TraceEvent package that knows how to take these events (and the stacks that are on some of them) and form 'causality stack' from them.

There are reason, however to believe that there are 'holes' in this mechanism. That is there are ways of using the Task library that do not log sufficient events (or perhaps TraceEvent does not recognize them), and thus causality is broken.

This issue is meant to track the end-to-end scenario. The end goal is that tools like AppInsights Profiler and PerfView (which both use the TraceEvent library), have sufficient information to always generate a useful 'stack trace' (causality trace).

• [ ] Create tests that insure we can do this causality stack reconstruction, including
  - [] Basic ASP.NET Core scenarios (e.g. MVC) at various points
  - [] More methodical testing that tries to use all the different APIs of Task and features of C# async
  and insure that we can get good stacks when waiting with these APIs being used to set up
  the causality chain.
• [] We go to some trouble to minimize the number of events logged by the task library. There is a good
  chance that this is what is causing some of the bugs. It would be useful to have a low level
  mechanism that is only turned on for testing that does not worry about efficiency, but logs at
  precisely the right time. This makes it easy to do the stack 'both ways' and then compare that they
  are the same. Thus we can take 'arbitrary' code (say all the ASP.NET tests) and run it through
  this harness that turns on these extra events and does the comparison of what we get
  to the 'gold standard' events, so we can find new problems (because we did not have code
  coverage, and add more targeted tests when we find new things.
• [] Today our TaskWait event does not indicate whether a task is immediately waiting on another task.
  This often happens when you have methods calling other async methods. It is VERY useful to
  indicate in the GUI that the time that all these nested Tasks are waiting on is EXPECTED to overhap
  (and thus just count it once). Today we use heuristics, we should fix it so that we simply say so
  in the event (and thus can give a better display to the user).
• [] Fix any issues that come up from that testing.

Note that our current approach is relatively expensive in that it needs two events to be fired for every blocking call. There may be ways to do better than this (by leveraging the information in the Task objects), so that is worth thinking about as part of this.

[mjsabby]

Today there are at least some causalities that we're unable to track.

In my experiments IO Dequeues use a different mechanism than the TplEventSource. It's called ThreadTransferSend

https://github.com/dotnet/coreclr/blob/746da72fbd0ad480be9b2eca147f74eea36d2b5f/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/FrameworkEventSource.cs#L680

The problem with tracking this is that you also need to track managed object movement, which can be cost prohibitive, so I'd like to solve this one as well.

I'll add more cases as I find them, but I'd love to get 100% causality for managed code.

[stephentoub]

Today our TaskWait event does not indicate whether a task is immediately waiting on another task.

@vancem, can you clarify this? Is there a code sample you could share and then the additional information you'd expect to be included in the event as a result?

[tommcdon]

@noahfalk @stephentoub any objections if we move this to future?

[stephentoub]

@tommcdon, it's hard for me to answer that as the initial work here seems to be exploratory to determine if there are gaps and then also address them. Do we have time in 3.0 to at least do the initial testing work to understand what the gaps are? Then we could decide whether we have any runway to fix the most impactful ones or whether we should push everything out. Of course, I also don't know what other important work you're triaging this against, so take this with a grain of salt.

[noahfalk]

If we created a new issue to track Mukul's specific example I'd be OK if the broader issue moved to Future. My impression (and feel free to say it doesn't match yours Stephen) is that we are tracking a significant number of concrete bugs and incomplete work in tracing/diagnostic scenarios, many of which are probably more severe than an occasional missing TPL event. This issue is asking for open ended testing and other than Mukul's example there is no certain return on the time invested. I think we've got enough known definitely customer impacting work that we aren't likely to get to things that are uncertain and unlikely to be critical.

[tommcdon]

Moving this to future for now, though we will try to conduct a spike to determine how much work is needed for the overall scenario

[bitbonk]

Is the goal of this issue to also have a a correct (meaningful) causality stack available in the regular Visual Studio debugger? When code makes heavy use of async await, it happens very often, that this causality stack is truncated when I look at the stack trace in the debugger (task view and parallel stacks view suffer from the same problem).

[noahfalk]

@bitbonk - If you have any specific examples where VS is showing the wrong result opening a bug would be great. Whether or not your issue would connect to this one is harder to say. VS has several different strategies for extracting the causality information including ETW events, debugger events, and direct memory analysis of the managed heap. Your scenario might use any of them depending on the details.

[lg2de]

With the help of @bitbonk and @ArndtMichael I can present some small programs today, which shows the insufficient debugability of Tasks.
All are build in the same manner:

1. The program file is intended as console application.
2. We are using .NET Core 3 preview 6.
3. Application must be started with debugging in Visual Studio. After a few seconds you should break the application (Break All).
   We expect to see the current location (waiting position) in the Task window of Visual Studio.

The following gists are providing source code for the console program and the currently visible information from Task window.
The list may be extended within the next days/weeks as soon we have identified additional reproducible issues.

• [ ] [Awaiting Task.Delay](https://gist.github.com/lg2de/05d112e65f4ec76d1cd949388510ca0d)
• [ ] [Awaiting TaskCompletionSource<T>.Task](https://gist.github.com/lg2de/e18cffae76a0e9bd73043cbc5b989cff)
• [ ] [Awaiting several Tasks accessing SemaphoreSlim](https://gist.github.com/lg2de/76f9f8dfaf9f0f451f88046cee5c9fa9)

Please drop me a note whether these information are sufficient to investigate.

[noahfalk]

Thanks @lg2de ! I reached out in email to some devs that work on Visual Studio debugger (I'm not sure if they have GitHub handles). @gregg-miskelly @andysterland

[noahfalk]

@r-ramesh

[r-ramesh]

Taking a look, also adding @mpeyrotc