debugging stack traces

[nikomatsakis]

Brief summary:

I don't honestly know! But people keep telling me async stack traces are hard to debug! Help me understand! Send me examples!

Optional details

• Which character(s) would be the best fit and why?
  • Alan: the experienced "GC'd language" developer, new to Rust
  • Grace: the systems programming expert, new to Rust
  • Niklaus: new programmer from an unconventional background
  • Barbara: the experienced Rust developer
• (Optional) Which project(s) would be the best fit and why?
  • Maybe the server project? Often it is necessary to debug problems with minimal information.
• (Optional) What are the key points or morals to emphasize?

[galich]

I've made an example of C# and Rust stack traces here https://github.com/galich/stacks

Observations:

1. Rust stack has a lot of noise, like tokio internal calls. As a user of the crate I'm mostly interested in reading stack that has my code. Note: that stack is produced by RUST_BACKTRACE=1, if we turn on RUST_BACKTRACE="full" we'll get even more entries, but that's okay, we asked for the full trace.
2. Rust stack contains 5 entries from my code, 3 of which are main. Granted I have async closure in main and that could explain 2 of them, and third is probably a result of #[tokio::main] work. But this can be disorienting to some less senior developers.
3. there are many {{closure}} lines, even in fns that has no closures internally. I suppose this is side effect of how async fn works.
4. C# version lists only calls in the code I've wrote.

If there is a crash in production I'll find C# issue much faster with simpler stack trace.

[stuhood]

One example: A deadlock involving async mutexes does not render as a smoking gun the same way a sync deadlock does.

[stuhood]

Non-blocking code can also be harder to profile for the same reason: stacktraces (and thus profilers) can't show you contention/time spent waiting on async locks, or time spent on IO.

[erickt]

One challenge would be how to debug live lock-ish issues between services using futures. On fuchsia pretty much everything is asynchronous. So when you have some client interacting with some other service, they both have executors driving the futures. So:

• client starts an executor
• client adds a future to the executor
• The future makes a call to some service.
• the executor suspends the future and waits on a kernel object for any channel to receive a message.
• For whatever reason the server does not reply, nor does it close the channel.

While fuchsia has some tools to help debug issues like this, the main technology we have to triage live-ish locks like this to set timeouts on our calls, and annotat most call sites with logs. Inevitably we forget some locations, and it becomes difficult to understand what happened.

My dream to try to debug issues like this would if there was some mechanism where we could ask the executor to wake up every pending future, then dump a backtrace of the future stack. Something like that would make it easy to detect when’s future is stuck waiting for something to happen.

[nikomatsakis]

@gilescope wrote on twitter:

One bit that’s missing in rust is linkage to get back to the line of code that put the initial async task on the runtime. I don’t think that happens out of the box yet.

[nikomatsakis]

@erickt that sounds like the start of a great story, and probably it's own issue -- I'm going to break it out. But it'd be awesome if you write up as a story!

[stuhood]

This one is more of a shot in the dark, but is it possible that async fns (and/or their interplay with monomorphization) break profiling which functions are hot due to having many distinct callers? This one is more challenging because the application it's an anecdote from has never been synchronous, so I cannot compare sync/async profiles side-by-side.

[nikomatsakis]

@stuhood it's certainly possible, can you give a bit more details about what happened in the case of the project? Also, were there spawn calls involved? What kind of tool was used for profiling? What did the results look like? Did you ever figure out a better picture of what was going on, and how?

[stuhood]

@stuhood it's certainly possible, can you give a bit more details about what happened in the case of the project? Also, were there spawn calls involved? What kind of tool was used for profiling? What did the results look like? Did you ever figure out a better picture of what was going on, and how?

I was not able to reproduce any issues in the area of duped/monomorphized functions, with/without spawn calls: there was only one copy of the async function definition. I created a little async project with a slow function: https://github.com/stuhood/async-profiling-honeypot ... and then profiled it with/without debug symbols on macOS using Instruments.

One thing that did jump out though, is that although the original async function's frame is in the stack, you also get a GenFuture::...::poll frame. Better than it was in the days of combinators, but still a bit noisy.

[gilescope]

If we had some kind of #[track_caller] for when giving tasks to executors that would help with that last mile of the stacktrace. I would have thought that if RUST_BACKTRACE=1 we should be able to filter out the boring bits of async - is it that we can't identify which frames they are? I bet there's many methods that would like to be able to set a flag to opt out of the filtered backtrace - i.e. the mechanism doesn't need to be async await specific.

I wonder if we should break out profiling (and memory profiling?) of async into separate stories because these are separate aspects but clearly we need tooling that understands async to see the true picture. I wonder if DWARF should have some cross-language support for async-await? I can't picture quite what that would look like... but we're not the only language to have async-await.