Inspecting tokio tasks with gdb
Table of contents
- 1. The problem with debugging async code
- 2. Building a GDB extension for task inspection
- 3. A showcase
- 4. Other async debugging and observability tools
- References
1. The problem with debugging async code
As someone coming to Rust mostly from C/C++ background, I usually reach for a debugger when things go sideways. gdb has saved me countless hours of CPU time that would've been wasted on recompiling after adding yet another bunch of debug prints.
It continued to serve me well when I moved to Rust, at least initially. While the debugging experience felt a lot less polished due to lacking pretty printers and first-class support of some language features, it still beat scattering dbg!() all over the code by a large margin. However, this changed when I switched jobs and started working on a large codebase built with tokio, riddled with async code. That's when my usual debugging approach started to crumble.
If you've ever tried to debug a hanging Tokio task, you probably know the struggle. And if you've been lucky enough to avoid that nuisance so far, let me demonstrate the difference between debugging a traditional threaded program versus one that uses an async work-stealing runtime like tokio.
First, let's take a look at the simple threaded program that does the following:
- Initializes shared state containing a boolean flag (protected by a mutex) and a condition variable.
- Spawns a background thread with a pointer to the shared state.
- Reads a single line from standard input
- Sets the flag and notifies the background thread
- Waits for the background thread to exit
- Background thread waits on the
Condvaruntil the flag is set, then exits.
Here's the complete source:
use std::{
io::BufRead, sync::{Arc, Condvar, Mutex}
};
type State = Arc<(Condvar, Mutex<bool>)>;
fn main() {
let state = State::default();
let handle = std::thread::spawn({
let state = state.clone();
move || {
let (cond, lock) = &*state;
let mut flag = lock.lock().unwrap();
while !*flag {
flag = cond.wait(flag).unwrap();
}
println!("flag = true");
}
});
std::io::stdin().lock().read_line(&mut String::new()).unwrap();
*state.1.lock().unwrap() = true;
state.0.notify_one();
handle.join().unwrap();
}
Listing 1: a simple multithreaded program.
Now, let's attach a debugger to this program and print backtraces of all threads:
(gdb) thread apply all bt 4
Thread 2 (Thread 0x7f8d017ff6c0 (LWP 20298) "condvar-threade"):
#0 0x00007f8d0191876d in syscall () from /usr/lib/libc.so.6
#1 0x00005602b4f784f5 in std::sys::pal::unix::futex::futex_wait () at library/std/src/sys/pal/unix/futex.rs:73
#2 std::sys::sync::condvar::futex::Condvar::wait_optional_timeout () at library/std/src/sys/sync/condvar/futex.rs:49
#3 std::sys::sync::condvar::futex::Condvar::wait () at library/std/src/sys/sync/condvar/futex.rs:33
(More stack frames follow...)
Thread 1 (Thread 0x7f8d01a147c0 (LWP 20224) "condvar-threade"):
#0 0x00007f8d0189f042 in ?? () from /usr/lib/libc.so.6
#1 0x00007f8d018931ac in ?? () from /usr/lib/libc.so.6
#2 0x00007f8d018931f4 in ?? () from /usr/lib/libc.so.6
#3 0x00007f8d0190da6e in read () from /usr/lib/libc.so.6
(More stack frames follow...)
I've limited the backtraces to 4 frames for brevity, but even this limited view gives us enough information to understand the program's state:
Thread 1(the main() thread) is waiting for a newline in libc's read() functionThread 2(the background thread) is waiting for a notification on the condition variable
Even in a more complex scenario where we didn't immediately understand why the background thread wasn't finishing, we could easily investigate further by poking the thread's frames and mutex state.
Async code is an entirely different story though, due to futures being compiled to state machines and N:M scheduling in tokio's work-stealing runtime (we will forget about the current thread scheduler for the sake of simplicity).
Let's now compare the results from the traditional threading program with a functionally similar async tokio program:
use std::sync::Arc;
use tokio::{
io::AsyncBufReadExt,
sync::Notify,
};
#[tokio::main(worker_threads=2)]
async fn main() {
let notify = Arc::new(Notify::new());
let handle = tokio::spawn({
let notify = notify.clone();
async move {
notify.notified().await;
println!("flag = true");
}
});
let mut stdin = tokio::io::BufReader::new(tokio::io::stdin());
let mut line = String::new();
stdin.read_line(&mut line).await.unwrap();
notify.notify_one();
handle.await.unwrap();
}
Listing 2: a simple multithreaded program but in async rust.
Again, let's attach the debugger and print backtraces:
(gdb) thread apply all bt
Thread 4 (Thread 0x7fcc201ff6c0 (LWP 30158) "tokio-runtime-w"):
#0 0x00007fcc2029f042 in ?? () from /usr/lib/libc.so.6
#1 0x00007fcc202931ac in ?? () from /usr/lib/libc.so.6
#2 0x00007fcc202931f4 in ?? () from /usr/lib/libc.so.6
#3 0x00007fcc2031acf5 in epoll_wait () from /usr/lib/libc.so.6
(More stack frames follow...)
Thread 3 (Thread 0x7fcc1fffe6c0 (LWP 30159) "tokio-runtime-w"):
#0 0x00007fcc2031876d in syscall () from /usr/lib/libc.so.6
#1 0x0000555eec1a37f1 in parking_lot_core::thread_parker::imp::ThreadParker::futex_wait (self=0x7fcc1fffe658, ts=...) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/parking_lot_core-0.9.12/src/thread_parker/linux.rs:112
#2 0x0000555eec1a30ac in parking_lot_core::thread_parker::imp::{impl#0}::park (self=0x7fcc1fffe658) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/parking_lot_core-0.9.12/src/thread_parker/linux.rs:66
#3 0x0000555eec1ac92a in parking_lot_core::parking_lot::park::{closure#0}<parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#0}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#1}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#2}> (thread_data=0x7fcc1fffe638) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/parking_lot_core-0.9.12/src/parking_lot.rs:635
(More stack frames follow...)
Thread 2 (Thread 0x7fcc1fdfd6c0 (LWP 30160) "tokio-runtime-w"):
#0 0x00007fcc2029f042 in ?? () from /usr/lib/libc.so.6
#1 0x00007fcc202931ac in ?? () from /usr/lib/libc.so.6
#2 0x00007fcc202931f4 in ?? () from /usr/lib/libc.so.6
#3 0x00007fcc2030da6e in read () from /usr/lib/libc.so.6
(...OMITTED...)
#28 0x000055e2977db517 in tokio::runtime::blocking::pool::Task::run (self=...) at src/runtime/blocking/pool.rs:161
#29 0x000055e2977db770 in tokio::runtime::blocking::pool::Inner::run (self=0x55e2c6174670, worker_thread_id=2) at src/runtime/blocking/pool.rs:516
#30 0x000055e2977dcbf4 in tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure#0} () at src/runtime/blocking/pool.rs:474
#31 0x000055e2978143c6 in std::sys::backtrace::__rust_begin_short_backtrace<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()> (f=<error reading variable: Cannot access memory at address 0x0>) at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/backtrace.rs:158
#32 0x000055e297802b72 in std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()> () at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/mod.rs:559
#33 0x000055e2977c8cf1 in core::panic::unwind_safe::{impl#23}::call_once<(), std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>> (self=...) at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panic/unwind_safe.rs:274
#34 0x000055e2977cca10 in std::panicking::catch_unwind::do_call<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>>, ()> (data=0x7eff733fcbe8) at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:590
#35 0x000055e29780a86b in __rust_try ()
#36 0x000055e297802761 in std::panicking::catch_unwind<(), core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>>> (f=...) at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:553
#37 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>>, ()> (f=...) at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:359
#38 std::thread::{impl#0}::spawn_unchecked_::{closure#1}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()> () at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/mod.rs:557
#39 0x000055e2977e68af in core::ops::function::FnOnce::call_once<std::thread::{impl#0}::spawn_unchecked_::{closure_env#1}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>, ()> () at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250
#40 0x000055e2978739bf in alloc::boxed::{impl#29}::call_once<(), dyn core::ops::function::FnOnce<(), Output=()>, alloc::alloc::Global> () at library/alloc/src/boxed.rs:1985
#41 std::sys::thread::unix::{impl#2}::new::thread_start () at library/std/src/sys/thread/unix.rs:126
#42 0x00007eff738969cb in ?? () from /usr/lib/libc.so.6
#43 0x00007eff7391aa0c in ?? () from /usr/lib/libc.so.6
Thread 1 (Thread 0x7fcc204631c0 (LWP 30063) "condvar-async"):
#0 0x00007fcc2031876d in syscall () from /usr/lib/libc.so.6
#1 0x0000555eec1a37f1 in parking_lot_core::thread_parker::imp::ThreadParker::futex_wait (self=0x7fcc20463158, ts=...) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/parking_lot_core-0.9.12/src/thread_parker/linux.rs:112
#2 0x0000555eec1a30ac in parking_lot_core::thread_parker::imp::{impl#0}::park (self=0x7fcc20463158) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/parking_lot_core-0.9.12/src/thread_parker/linux.rs:66
#3 0x0000555eec1ac92a in parking_lot_core::parking_lot::park::{closure#0}<parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#0}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#1}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#2}> (thread_data=0x7fcc20463138) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/parking_lot_core-0.9.12/src/parking_lot.rs:635
(...OMITTED...)
#19 0x000055e2977bbac3 in tokio::runtime::scheduler::multi_thread::MultiThread::block_on<condvar_async::main::{async_block_env#0}> (self=0x7fff33245f00, handle=0x7fff33245f28, future=...) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/mod.rs:86
#20 0x000055e2977af089 in tokio::runtime::runtime::Runtime::block_on_inner<condvar_async::main::{async_block_env#0}> (self=0x7fff33245ef8, future=...) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/runtime.rs:370
#21 0x000055e2977af311 in tokio::runtime::runtime::Runtime::block_on<condvar_async::main::{async_block_env#0}> (self=0x7fff33245ef8, future=...) at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/runtime.rs:342
#22 0x000055e2977c11ae in condvar_async::main () at src/main.rs:26
Things look a bit more complicated here, and a lot less informative. Let's dive in and break down what we're actually seeing here.
Thread 1is ourmain()thread where we implicitly calledblock_onvia the#[tokio::main]macro to start the runtime. With themultithreadscheduler, this thread directly drives the root future, which is ourasync main()function.This fact gives us an opportunity to directly inspect the state of the
main()future:(gdb) f 22 #22 0x000055a9ff3351ae in condvar_async::main () at src/main.rs:26 26 handle.await.unwrap(); (gdb) info local body = condvar_async::main::{async_block_env#0}::Unresumedbodyvariable is generated bytokio::mainmacro and holds the actualmainfuture.Unresumedis the initial state of the future, which means that it was never been polled yet, which means that we must be awaiting for thestdin.read_line()to finish.The rest of the backtrace are tokio internals, which give us little information on what our code is actually doing.
We got lucky with the main thread, but is about to end as we are going to inspect other threads.
Thread 2is a background thread spawned by Tokio's I/O driver to handle the actual reading from stdin. At least on Linux, Tokio uses a thread pool for blocking file I/O operations rather than relying on epoll and AIO (see [ 1 ]). Work on io_uring support, which could theoretically resolve many of the issues with epoll and AIO, appears to have stalled for now.Thread 3andThread 4are tokio's core worker threads.Thread 3is currently parked, waiting to pick up work.Thread 4is a worker thread that, due to no available work, took the ownership of the driver and entered theepollloop. This is most likely the thread that was executing our background task.
As we can see, there's little to no information about task states on the worker threads' stacks. While we were able to inspect the state of the main() task, any spawned task that's currently awaiting is completely invisible to the traditional debugger.
It's a bit of comparing apples to oranges due to language and runtime differences, but Go's debugging story looks a lot better in comparison. There we have Delve, which is a quite mature Go-native debugger coming with full goroutine support. There's also runtime-gdb.py, a GDB extension that adds support for some Go features, namely goroutine inspection.
As for Rust-first debuggers and tooling in general, there are indeed promising projects that we will overview in the final section. However, I feel like Rust's debugging story still lags behind Go's and is well behind the mastodons like C and C++.
In this article, we will try to narrow this gap just a little bit by implementing a part of Go's runtime-gdb.py info goroutines feature, but for inspecting Tokio tasks. We'll write a simple python script that dumps the state of all active tasks on the runtime.
Note that the script will require debug symbols to work, but this is rarely a problem in practice, since can always compile your binary in the release mode with debug symbols enabled, and split them into a separate .debug file. It can be then compressed and uploaded on the target host when needed. Alternatively, you can use remote debugging with gdbserver and keep the .debug file on your development machine.
2. Building a GDB extension for task inspection
To build something similar to info goroutines, we need to:
- Get an access to tokio's worker thread state.
- Iterate over the list of all spawned tokio tasks.
- Inspect the state of each task's root future.
2.1. Accessing scheduler context
To iterate over all Tokio tasks, we first need to gain access to Tokio’s internal global state. To understand how this might be done, let’s take a look at what tokio::task::spawn does internally (the code is simplified for brevity):
pub fn spawn<F>(future: F) -> JoinHandle<F::Output> {
spawn_inner(future, SpawnMeta::new_unnamed(fut_size))
}
pub(super) fn spawn_inner<T>(future: T, meta: SpawnMeta<'_>) -> JoinHandle<T::Output> {
let id = task::Id::next();
let task = crate::util::trace::task(future, "task", meta, id.as_u64());
context::with_current(|handle| handle.spawn(task, id, meta.spawned_at))
}
pub(crate) fn with_current<F, R>(f: F) -> Result<R, TryCurrentError> {
CONTEXT.try_with(|ctx| ctx.current.handle.borrow().as_ref().map(f))
}
So there's some shared state stored in the thread-local CONTEXT variable:
macro_rules! tokio_thread_local {
static CONTEXT: Context = const {
Context {
thread_id: Cell::new(None),
current: current::HandleCell::new(),
scheduler: Scoped::new(),
current_task_id: Cell::new(None),
runtime: Cell::new(EnterRuntime::NotEntered),
rng: Cell::new(None),
budget: Cell::new(coop::Budget::unconstrained()),
}
}
}
If we pause our asynchronous Tokio program, switch to a worker thread, and poke into the CONTEXT variable, we can observe that it contains meaningful data. The most interesting part for our purposes is the current.handle field, which should point to the scheduler’s Handle when the context is properly initialized.
(gdb) p ('tokio::runtime::context::Context')'tokio::runtime::context::CONTEXT::{{constant}}::{{closure}}::VAL'
$1 = {thread_id = {value = {value = {0, None = {<No data fields>}}}}, current = {handle = {borrow = {value = {value = 0}}, value = {value = {1, Some = {__0 = {1, MultiThread = {__0 = {ptr = {
pointer = 0x5556cfced210}, phantom = {<No data fields>}, alloc = {<No data fields>}}}}}}}}, depth = {value = {value = 2}}}, scheduler = {inner = {value = {
value = 0x7e5c158be910}}}, current_task_id = {value = {value = {13, Some = {__0 = {__0 = {__0 = {__0 = 13}}}}}}}, runtime = {value = {value = {1 '\001', Entered = {
allow_block_in_place = true}}}}, rng = {value = {value = {1, Some = {__0 = {one = 1225490803, two = 1985358118}}}}}, budget = {value = {value = {__0 = {0 '\000',
None = {<No data fields>}}}}}}
The next step is to figure out where the actual task queue lives inside the Handle.
2.2. Walking the task list
Let's take a look at the tokio::runtime::scheduler::multi_thread::handle::Handle struct:
/// Handle to the multi thread scheduler
pub(crate) struct Handle {
/// Task spawner
pub(super) shared: worker::Shared,
/// Resource driver handles
pub(crate) driver: driver::Handle,
/// Blocking pool spawner
pub(crate) blocking_spawner: blocking::Spawner,
/// Current random number generator seed
pub(crate) seed_generator: RngSeedGenerator,
/// User-supplied hooks to invoke for things
pub(crate) task_hooks: TaskHooks,
}
And then at the worker::Shared:
/// State shared across all workers
pub(crate) struct Shared {
/// Per-worker remote state. All other workers have access to this and is
/// how they communicate between each other.
remotes: Box<[Remote]>,
/// Global task queue used for:
/// 1. Submit work to the scheduler while **not** currently on a worker thread.
/// 2. Submit work to the scheduler when a worker run queue is saturated
pub(super) inject: inject::Shared<Arc<Handle>>,
/// Coordinates idle workers
idle: Idle,
/// Collection of all active tasks spawned onto this executor.
pub(crate) owned: OwnedTasks<Arc<Handle>>,
/// Data synchronized by the scheduler mutex
pub(super) synced: Mutex<Synced>,
// .. some more fields, omitted
}
What we are interested in here is the owned field, which represents the worker thread's task queue. There is also a global task queue accessible via the inject field, but we won't focus on it. In practice, tasks rarely remain there for long, as they typically end up in an executor-local queue soon enough.
What is OwnedTasks then?
pub(crate) struct OwnedTasks<S: 'static> {
list: List<S>,
pub(crate) id: NonZeroU64,
closed: AtomicBool,
}
type List<S> = sharded_list::ShardedList<Task<S>, <Task<S> as Link>::Target>;
pub(crate) struct ShardedList<L, T> {
lists: Box<[Mutex<LinkedList<L, T>>]>,
added: MetricAtomicU64,
count: MetricAtomicUsize,
shard_mask: usize,
}
pub(crate) struct LinkedList<L, T> {
/// Linked list head
head: Option<NonNull<T>>,
/// Linked list tail
tail: Option<NonNull<T>>,
/// Node type marker.
_marker: PhantomData<*const L>,
}
So it is basically a shared intrusive linked list of task handles. And the task handle is represented by Task<S> struct, where S is scheduler type:
/// An owned handle to the task, tracked by ref count.
#[repr(transparent)]
pub(crate) struct Task<S: 'static> {
raw: RawTask,
_p: PhantomData<S>,
}
/// Raw task handle
#[derive(Clone)]
pub(crate) struct RawTask {
ptr: NonNull<Header>,
}
#[repr(C)]
pub(crate) struct Header {
/// Task state.
pub(super) state: State,
/// Pointer to next task, used with the injection queue.
pub(super) queue_next: UnsafeCell<Option<NonNull<Header>>>,
/// Table of function pointers for executing actions on the task.
pub(super) vtable: &'static Vtable,
// .. omitted some fields for brevity
}
Most important fields here are:
state-- a set of bitflags encoding scheduler state of the task (e.g.b0001means running,b0010means complete)vtable-- the vtable of the future. Most importantly, it contains thepoll()function pointer used to drive the task future.
So, in theory, all we need to do is walk this sharded list, take a task handle, and then… what? At first glance, there don’t seem to be any futures stored anywhere at all.
Turns out, this is an old C trick similar to container_of in Linux kernel is being played here. In RawTask, we have a pointer to the Header part of the task. But the full task state is represented by Cell<S> type:
#[repr(C)]
pub(super) struct Cell<T: Future, S> {
/// Hot task state data
pub(super) header: Header,
/// Either the future or output, depending on the execution stage.
pub(super) core: Core<T, S>,
/// Cold data
pub(super) trailer: Trailer,
}
Core<T, S> stores actual future state and has dynamic size. And Trailer contains prev/next pointers for traversing the linked list. Exactly what we needed!
/// Cold data is stored after the future. Data is considered cold if it is only
/// used during creation or shutdown of the task.
pub(super) struct Trailer {
/// Pointers for the linked list in the `OwnedTasks` that owns this task.
pub(super) owned: linked_list::Pointers<Header>,
/// Consumer task waiting on completion of this task.
pub(super) waker: UnsafeCell<Option<Waker>>,
/// Optional hooks needed in the harness.
pub(super) hooks: TaskHarnessScheduleHooks,
}
struct PointersInner<T> {
/// The previous node in the list. null if there is no previous node.
prev: Option<NonNull<T>>,
/// The next node in the list. null if there is no previous node.
next: Option<NonNull<T>>,
/// This type is !Unpin due to the heuristic from:
/// <https://github.com/rust-lang/rust/pull/82834>
_pin: PhantomPinned,
}
So it appers that all we need to do is to find out the concrete T and S for the Cell<T, S> type and then cast the *Header pointer to *Cell<T, S>. S is tied to the scheduler type and is effectively fixed. T is the type of the root future of the task and we need to somehow "unerase" it from the Vtable.
Turns out, we can leverage the poll function pointer to recover the symbol name of the pointee. If we resolve a symbol at the address referenced by the poll function pointer, we end up with something like this:
tokio::runtime::task::raw::poll<stuck_task_example::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>
The resolved symbol name has our future type encoded as the first generic argument of the raw::poll. So we just need to parse the symbol name and extract the future type, and then construct the proper Cell<T, S> type from that.
2.3. Inspecting the task's future
Once we have the Cell<T, S>, inspecting the future state becomes easy, as the future itself is stored in the core field of type Core<T, S>:
#[repr(C)]
pub(super) struct Core<T: Future, S> {
/// Scheduler used to drive this future.
pub(super) scheduler: S,
/// The task's ID, used for populating `JoinError`s.
pub(super) task_id: Id,
/// Either the future or the output.
pub(super) stage: CoreStage<T>,
// .. some fields are omitted
}
pub(super) struct CoreStage<T: Future> {
stage: UnsafeCell<Stage<T>>,
}
/// Either the future or the output.
#[repr(C)]
pub(super) enum Stage<T: Future> {
Running(T),
Finished(super::Result<T::Output>),
Consumed,
}
If the task's future is still running, we can access its state via the Stage::Running variant. From there, all that remains is to print the T value.
2.4. Complete implementation
Let's draw the rest of the owl and write a script using GDB Python API that will print the state of all tasks spawned on runtime:
from gdb import *
import re
class TokioTasks (gdb.Command):
"""Displays the state of root futures for all active tokio tasks"""
def __init__ (self):
super (TokioTasks, self).__init__ ("tokio-tasks", gdb.COMMAND_USER)
def invoke(self, arg, from_tty):
# get runtime context of the current thread from the thread-local CONTEXT variable
ctx = parse_and_eval("('tokio::runtime::context::Context')'tokio::runtime::context::CONTEXT::{{constant}}::{{closure}}::VAL'")
try:
handle = ctx['current']['handle']['value']['value']['Some']['__0']['MultiThread']['__0']['ptr']['pointer']['data']
except:
print("No multithreaded Tokio runtime context found")
return
# `lists: Box<[Mutex<LinkedList<L, T>>]>` field of the `ShardedList<L, T>`
lists = handle['shared']['owned']['list']['lists']
# number of shards
shards = int(lists['length'])
for i in range(0, shards):
try:
# `LinkedList::<L, T>::head` field
next_task = lists['data_ptr'][i]['__1']['data']['value']['head']
# go over the task list
while True:
try:
# try to get a pointer to the `Header` if the list is non empty (head is `Some(_)`)
header_ptr = next_task['Some']['__0']['pointer']
except:
# task list is empty
break
# get the poll function symbol from the poll function address in the vtable
poll = header_ptr[0]["vtable"]["poll"]
poll_block = block_for_pc(int(poll))
pollfn_name = poll_block.function.name
# parse future type name from the poll function
future_type_name = re.match('tokio::runtime::task::raw::poll<(.*), alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>', pollfn_name)[1]
sched_type_name = 'alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>'
# lookup future symbol from parsed type name
future_sym, _ = lookup_symbol(future_type_name)
future_type = future_sym.type
# construct cell type and cast Header to Cell
cell_name = f"tokio::runtime::task::core::Cell<{future_type.name}, {sched_type_name}>"
cell_typ = lookup_type(cell_name)
cell = header_ptr.cast(cell_typ.pointer())
# try to get the future state from `Core`
try:
state = cell[0]['core']['stage']['stage']['__0']['value']['Running']['__0']
except:
continue
# print future type and address, so we can inspect it later from GDB CLI
print(f"future = {state.type} at {state.address}:")
# print future state
print(state.format_string(styling = True, pretty_arrays = True, pretty_structs = True, symbols = True))
# go to next task in the list
next_task = cell[0]['trailer']['owned']['inner']['value']['next']
except Exception as e:
print(f"Exception during walking the task list on the shard {i}: {e}")
pass
TokioTasks()
A more elaborate and polished version of the above script can be found here: [ 2 ].
3. A showcase
Let's test our script and try to inspect the state of an example program with multiple tasks stuck in different ways.
3.1 The example program
Here's the program we will be inspecting:
use tokio::net::TcpListener;
use tokio::io::AsyncWriteExt;
use tokio::signal::ctrl_c;
#[tokio::main(worker_threads = 4)]
async fn main() {
// start TCP server task
let _server_task = {
let listener = TcpListener::bind("127.0.0.1:1111").await.unwrap();
tokio::spawn(async move {
loop {
let (mut stream, addr) = listener.accept().await.unwrap();
println!("new connection from {}", addr);
stream.write_all(b"hello").await.unwrap();
}
})
};
// start SIGINT handler
let signal_task = tokio::spawn(async move {
ctrl_c().await.unwrap();
println!("Received Ctrl-C first time...");
ctrl_c().await.unwrap();
println!("Received Ctrl-C once again, exiting...");
});
// start task with a select
tokio::spawn(async move {
let mut t1 = tokio::time::interval(std::time::Duration::from_secs(5));
let mut t2 = tokio::time::interval(std::time::Duration::from_secs(10));
loop {
tokio::select! {
_ = t1.tick() => {
eprint!("^");
}
_ = t2.tick() => {
eprint!("_");
}
}
}
});
// start two tasks that will deadlock on mutexes
let m1 = std::sync::Arc::new(tokio::sync::Mutex::new(()));
let m2 = std::sync::Arc::new(tokio::sync::Mutex::new(()));
tokio::spawn({
let m1 = m1.clone();
let m2 = m2.clone();
async move {
let _guard1 = m1.lock().await;
tokio::time::sleep(std::time::Duration::from_secs(1)).await;
let _guard2 = m2.lock().await;
}
});
tokio::spawn(
async move {
let _guard2 = m2.lock().await;
tokio::time::sleep(std::time::Duration::from_secs(1)).await;
let _guard1 = m1.lock().await;
}
);
// exit when Ctrl+C is hit twice
signal_task.await.unwrap();
}
Our showcase program consists of the following tasks:
- A TCP server that will accepts a connection, responds with a
hellobyte string, and then drop the connection. - A SIGINT handler task that exits after receiving SIGINT twice.
- A task using
select!that prints to stdout in a loop at regular intervals. - Two tasks that intentionally deadlock on a pair of mutexes.
Let's list the tasks first, and then inspect the state of each one. For this demo, we will use the improved version of the script ([ 2 ]).
(gdb) source tokio.py
(gdb) tokio-tasks
■ id = 13 shard = 13
stuck_task_example::main::{async_block#0}::{async_block_env#0}
■ id = 14 shard = 14
stuck_task_example::main::{async_block#0}::{async_block_env#1}
■ id = 15 shard = 15
stuck_task_example::main::{async_block#0}::{async_block_env#2}
■ id = 16 shard = 16
stuck_task_example::main::{async_block#0}::{async_block_env#3}
■ id = 17 shard = 17
stuck_task_example::main::{async_block#0}::{async_block_env#4}
(gdb) info line 'stuck_task_example::main::{async_block#0}::{async_block#0}'
Line 11 of "src/main.rs" starts at address 0x55d410ff5660 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h1a8598fd063c3d35E>
and ends at 0x55d410ff5677 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h1a8598fd063c3d35E+23>.
(gdb) info line 'stuck_task_example::main::{async_block#0}::{async_block#1}'
Line 23 of "src/main.rs" starts at address 0x55d410ff6150 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h2bb871757383f6cfE>
and ends at 0x55d410ff6160 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h2bb871757383f6cfE+16>.
(gdb) info line 'stuck_task_example::main::{async_block#0}::{async_block#2}'
Line 32 of "src/main.rs" starts at address 0x55d410ff63b0 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17heb3087c498a52962E>
and ends at 0x55d410ff63bd <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17heb3087c498a52962E+13>.
(gdb) info line 'stuck_task_example::main::{async_block#0}::{async_block#3}'
Line 56 of "src/main.rs" starts at address 0x55d410ff6570 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h1dd01955e079fa4fE>
and ends at 0x55d410ff6583 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h1dd01955e079fa4fE+19>.
(gdb) info line 'stuck_task_example::main::{async_block#0}::{async_block#4}'
Line 64 of "src/main.rs" starts at address 0x55d410ff6880 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h58579c41b2106e64E>
and ends at 0x55d410ff6893 <_ZN18stuck_task_example4main28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17h58579c41b2106e64E+19>.
The script will print the ID, shard number and the type of the future for each task. We can inspect future types to get more information, e.g. definition location. Here async_block#0 is a symbol of an async block generated by the compiler. And async_block_env#0 is the corresponding future state.
In theory, we can extend the script to print line information for tree future tree automatically, but this is harder than it looks, since in the real applications the future types are going to be a bit more complex.
Let's now inspect each task in detail.
3.2. TCP server task
Let's inspect the state of the TCP server task:
(gdb) tokio-tasks state 13
state of type struct stuck_task_example::main::{async_block#0}::{async_block_env#0} at 0x55d443d118b8 :
{
__state = 3 '\003',
3 = {
__awaitee = {__state = 3 '\003', 3 = {__awaitee = {__state = 3 '\003', 3 = {self = 0x55d443d118b8, interest = {__0 = 1}, f = {_ref__self = 0x55d443d118b8}, __awaitee = {__state = 3 '\003', 3 = {__awaitee = {__state = 3 '\003', 3 = {__awaitee = {scheduled_io = 0x55d443d11780, state = tokio::runtime::io::scheduled_io::State::Waiting, waiter = {value = {pointers = {inner = {value = {prev = {0, None = {<No data fields>}}, next = {0, None = {<No data fields>}}, _pin = {<No data fields>}}}}, waker = {94369307134072, Some = {__0 = {waker = {data = 0x55d443d11880, vtable = 0x55d411078878 <tokio::runtime::task::waker::WAKER_VTABLE>}}}}, interest = {__0 = 1}, is_ready = false, _p = {<No data fields>}}}}, self = 0x55d443d11780, interest = {__0 = 1}}}, self = 0x55d443d118b8, interest = {__0 = 1}}}, self = 0x55d443d118b8, interest = {__0 = 1}, f = {_ref__self = 0x55d443d118b8}}}, self = 0x55d443d118b8}},
listener = {io = {io = {9, Some = {__0 = {inner = {state = {<No data fields>}, inner = {__0 = {inner = {__0 = {__0 = {fd = {__0 = 9}}}}}}}}}}, registration = {handle = {1, MultiThread = {__0 = {ptr = {pointer = 0x55d443d0e200}, phantom = {<No data fields>}, alloc = {<No data fields>}}}}, shared = {ptr = {pointer = 0x55d443d11700}, phantom = {<No data fields>}, alloc = {<No data fields>}}}}
}
}
}
This is the full state of the root level future, including nested futures generated by accept().await and .write_all(..).await. From this state dump we can immediately see that the root future generated by the async block is in state 3:
(gdb) ptype 'stuck_task_example::main::{async_block#0}::{async_block_env#0}'
type = struct stuck_task_example::main::{async_block#0}::{async_block_env#0} {
struct stuck_task_example::main::{async_block#0}::{async_block_env#0}::Unresumed 0;
struct stuck_task_example::main::{async_block#0}::{async_block_env#0}::Returned 1;
struct stuck_task_example::main::{async_block#0}::{async_block_env#0}::Panicked 2;
struct stuck_task_example::main::{async_block#0}::{async_block_env#0}::Suspend0 3;
struct stuck_task_example::main::{async_block#0}::{async_block_env#0}::Suspend1 4;
}
State 3 corresponds to Suspend0, which is the first await point at main.rs:13 on accept().await.
The compiler is even nice enough to generate line information for these states, as seen in this DWARF dump (llvm-dwarfdump):
0x0000f58c: DW_TAG_member
DW_AT_name ("3")
DW_AT_type (0x0000f5e4 "stuck_task_example::main::{async_block#0}::{async_block_env#0}::Suspend0")
DW_AT_decl_file ("/home/alexey/Dev/lab/gdb-tokio-tasks/stuck-task-example/src/main.rs")
DW_AT_decl_line (13)
DW_AT_alignment (8)
DW_AT_data_member_location (0x00)
Unfortunately, this information seems to be unavailable from GDB, so we can't use it directly. We could probably just parse the DWARF info ourselves and find the source location for each state. That would let us print proper future backtraces with source locations.
3.3. SIGINT handler task
(gdb) tokio-tasks state 14
state of type struct stuck_task_example::main::{async_block#0}::{async_block_env#1} at 0x55d443d11ab8 :
{
__state = 3 '\003',
3 = {
__awaitee = {__state = 3 '\003', 3 = {__0 = {inner = {inner = {boxed = {pointer = {pointer = 0x7f36dc000d60, vtable = 0x55d4110794e0 <anon.58e274e89ad7334f70cbb960740bdc7e.23.llvm>}}}}}, __1 = {139873595952480, Continue = {__0 = {inner = {inner = {boxed = {pointer = {pointer = 0x7f36dc000d60, vtable = 0x55d4110794e0 <anon.58e274e89ad7334f70cbb960740bdc7e.23.llvm>}}}}}}}, __awaitee = {__state = 3 '\003', 3 = {__awaitee = {__state = 3 '\003', 3 = {__awaitee = {f = {_ref__self = 0x55d443d11ac0}}, self = 0x55d443d11ac0}}, self = 0x55d443d11ac0}}}}
}
}
(gdb) ptype 'stuck_task_example::main::{async_block#0}::{async_block_env#1}'
type = struct stuck_task_example::main::{async_block#0}::{async_block_env#1} {
struct stuck_task_example::main::{async_block#0}::{async_block_env#1}::Unresumed 0;
struct stuck_task_example::main::{async_block#0}::{async_block_env#1}::Returned 1;
struct stuck_task_example::main::{async_block#0}::{async_block_env#1}::Panicked 2;
struct stuck_task_example::main::{async_block#0}::{async_block_env#1}::Suspend0 3;
struct stuck_task_example::main::{async_block#0}::{async_block_env#1}::Suspend1 4;
}
Our SIGINT handler is sleeping on the first await point, waiting for the first signal. Let's send it SIGINT and see what happens:
(gdb) signal SIGINT
(gdb) tokio-tasks state 14
state of type struct stuck_task_example::main::{async_block#0}::{async_block_env#1} at 0x55d443d11ab8 :
{
__state = 4 '\004',
4 = {
__awaitee = {__state = 3 '\003', 3 = {__0 = {inner = {inner = {boxed = {pointer = {pointer = 0x7f36dc000d60, vtable = 0x55d4110794e0 <anon.58e274e89ad7334f70cbb960740bdc7e.23.llvm>}}}}}, __1 = {139873595952480, Continue = {__0 = {inner = {inner = {boxed = {pointer = {pointer = 0x7f36dc000d60, vtable = 0x55d4110794e0 <anon.58e274e89ad7334f70cbb960740bdc7e.23.llvm>}}}}}}}, __awaitee = {__state = 3 '\003', 3 = {__awaitee = {__state = 3 '\003', 3 = {__awaitee = {f = {_ref__self = 0x55d443d11ac0}}, self = 0x55d443d11ac0}}, self = 0x55d443d11ac0}}}}
}
}
Here we can see we've moved to the 4th state, which is the second await point, waiting for the second signal.
3.4. select! task
Let's inspect the select! task now.
(gdb) tokio-tasks state 15 -p
state of type struct stuck_task_example::main::{async_block#0}::{async_block_env#2} at 0x55d443d11c38 :
{
__state = 3 '\003',
3 = {
t1 = {
delay = {
pointer = 0x7f36cc001d70
},
period = {
secs = 5,
nanos = {
__0 = 0
}
},
missed_tick_behavior = tokio::time::interval::MissedTickBehavior::Burst
},
t2 = {
delay = {
pointer = 0x7f36cc001df0
},
period = {
secs = 10,
nanos = {
__0 = 0
}
},
missed_tick_behavior = tokio::time::interval::MissedTickBehavior::Burst
},
disabled = 0 '\000',
futures = {
__0 = {
__state = 3 '\003',
3 = {
__awaitee = {
f = {
_ref__self = 0x55d443d11c38
}
},
self = 0x55d443d11c38
}
},
__1 = {
__state = 3 '\003',
3 = {
__awaitee = {
f = {
_ref__self = 0x55d443d11c58
}
},
self = 0x55d443d11c58
}
}
},
__awaitee = {
f = {
_ref__disabled = 0x55d443d11cb8 "",
_ref__futures = 0x55d443d11c78
}
}
}
}
Here's what we see:
futures-- a tuple of futures generated by theselect!macro.disabled-- a bitmask of disabled branches. A branch can become disabled either due to a failed precondition, or when its corresponding future becomes ready.t1,t2-- timer objects.
And here's the compiler-generated task future state type, where we can see the types of the fields above:
(gdb) ptype 'stuck_task_example::main::{async_block#0}::{async_block_env#2}::Suspend0'
type = struct stuck_task_example::main::{async_block#0}::{async_block_env#2}::Suspend0 {
struct tokio::time::interval::Interval t1;
struct tokio::time::interval::Interval t2;
u8 disabled;
struct (tokio::time::interval::{impl#2}::tick::{async_fn_env#0}, tokio::time::interval::{impl#2}::tick::{async_fn_env#0}) futures;
struct core::future::poll_fn::PollFn<stuck_task_example::main::{async_block#0}::{async_block#2}::{closure_env#0}> __awaitee;
}
Here we can also see the child PollFn future that select! uses internally to poll branches via poll_fn().
We can also check the future type of one of the branches:
(gdb) ptype 'tokio::time::interval::{impl#2}::tick::{async_fn_env#0}::Suspend0'
type = struct tokio::time::interval::{impl#2}::tick::{async_fn_env#0}::Suspend0 {
struct core::future::poll_fn::PollFn<tokio::time::interval::{impl#2}::tick::{async_fn#0}::{closure_env#0}> __awaitee;
struct tokio::time::interval::Interval *self;
}
Here we see the back pointer to the timer object (self) and, again, the PollFn, because tick() internally uses poll_fn too.
3.5. Mutex deadlock tasks
Let's inspect the last two tasks. Those are probably the most interesting ones.
These two tasks demonstrate a typical deadlock: the first task locks mutex m1 and then tries to acquire m2, while the second does the opposite.
Let's look at the first task's state to see what this deadlock looks like under the debugger.
(gdb) tokio-tasks state 16
state of type struct stuck_task_example::main::{async_block#0}::{async_block_env#3} at 0x55d443d11db8 :
{
__state = 5 '\005',
5 = {
_guard1 = { lock = 0x55d443d11820 },
__awaitee = {
__state = 3 '\003',
3 = {
__awaitee = {
__state = 3 '\003',
3 = {
__awaitee = {__state = 4 '\004', 4 = {__awaitee = {node = {state = {inner = {value = {v = {value = 1}}}}, waker = {__0 = {value = {94369307134072, Some = {__0 = {waker = {data = 0x55d443d11d80, vtable = 0x55d411078878 <tokio::runtime::task::waker::WAKER_VTABLE>}}}}}}, pointers = {inner = {value = {prev = {0, None = {<No data fields>}}, next = {0, None = {<No data fields>}}, _pin = {<No data fields>}}}}, _p = {<No data fields>}}, semaphore = 0x55d443d11a20, num_permits = 1, queued = true}, self = 0x55d443d11a20}},
_ref__self = 0x55d443d11a20
}
},
self = 0x55d443d11a20
}
},
m1 = {ptr = {pointer = 0x55d443d11810}, phantom = {<No data fields>}, alloc = {<No data fields>}},
m2 = {ptr = {pointer = 0x55d443d11a10}, phantom = {<No data fields>}, alloc = {<No data fields>}}
}
}
(gdb) ptype 'stuck_task_example::main::{async_block#0}::{async_block_env#3}'
type = struct stuck_task_example::main::{async_block#0}::{async_block_env#3} {
struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Unresumed 0;
struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Returned 1;
struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Panicked 2;
struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Suspend0 3;
struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Suspend1 4;
struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Suspend2 5;
}
(gdb) ptype 'stuck_task_example::main::{async_block#0}::{async_block_env#3}::Suspend2'
type = struct stuck_task_example::main::{async_block#0}::{async_block_env#3}::Suspend2 {
struct tokio::sync::mutex::MutexGuard<()> _guard1;
struct tokio::sync::mutex::{impl#10}::lock::{async_fn_env#0}<()> __awaitee;
struct alloc::sync::Arc<tokio::sync::mutex::Mutex<()>, alloc::alloc::Global> m1;
struct alloc::sync::Arc<tokio::sync::mutex::Mutex<()>, alloc::alloc::Global> m2;
}
What do we see here?
We're in state 5, which is the second .await point where we're trying to lock m2. The Arc<Mutex> is allocated at 0x55d443d11810, and the 16-byte difference comes from the Arc reference counters.
If we look closely at the lock() future state, we can see a field: semaphore = 0x55d443d11a20, which points inside the m2 mutex object.
Tokio uses counting semaphores for mutexes internally, so this semaphore field belongs to the Acquire object, which in turn references the semaphore field of the Mutex we're trying to acquire.
// From tokio::sync::batch_semaphore
pub(crate) struct Acquire<'a> {
node: Waiter,
semaphore: &'a Semaphore,
num_permits: usize,
queued: bool,
}
pub struct Mutex<T: ?Sized> {
#[cfg(all(tokio_unstable, feature = "tracing"))]
resource_span: tracing::Span,
s: semaphore::Semaphore,
c: UnsafeCell<T>,
}
Inspecting the second task will give use the similar, but inverse picture, so I'll omit that.
4. Other async debugging and observability tools
As a little bonus, let's look at some existing tools that can help with debugging async Rust applications, specifically built with Tokio. The list below isn't anywhere near complete, and mostly includes tools I have some experience with.
4.1. Tokio console
Homepage: github.com/tokio-rs/console
This is probably the most famous tool out there. It works by instrumenting various events inside Tokio using the tracing infrastructure. It collects those events and sends them over a socket. The tokio-console CLI tool can then connect, aggregate the data, and display it in a pretty top-like TUI.
Here's how our example app looks like in the tokio-console: 
Here we can see the list of our tasks, the root future location and various stats that can come handy if you suspect that some of your tasks/futures wake up too often (Polls) or block for too long (Busy).
We see that all futures are sleeping, except for the ID 10, which is the select! task with a timer, which gets woken up every 5 seconds.
If we select a task and press enter, we'll get to the detailed task info screen. Among other things, it shows histograms of the task's polling and scheduling times:

Another important piece is the resources screen, activated with the r key:

It shows most of the driver primitives (e.g. timers and locks) and their states. Here we can clearly see our tasks deadlocked on mutexes (IDs 4 and 7), along with the timers created by the select! task. In this case, we could have figured out which mutexes caused the deadlock just from this screen and by digging through the source code.
Can be used for:
- Finding badly behaving tasks/futures (too many wake-ups, too much blocking, lost wakers when writing custom futures).
- Debugging problems with large scheduling latencies (usually caused by badly behaving tasks or too many running tasks).
- Debugging deadlocks and resources misuses.
Can not be used for:
- Getting task backtraces.
- Deep inspection of the task state.
Notes and caveats:
- Target application requires instrumentation and integration with
console-subscriber. - Target application doesn't need debug symbols for tokio console to work.
4.2 Tokio unstable task dump feature
Docs: docs.rs/tokio/latest/tokio/runtime/struct.Handle.html#method.dump
This is an unstable tokio feature that allows to get task backtraces for all spawned tasks. It is still considered experimental, so be warned.
At a high level, this feature works by capturing a backtrace for every task during the poll:
- First, it enables the task dump mode in the shared state, so workers know that the next poll must be made with leaf future tracing enabled.
- Then all tasks are woken up, worker threads start to pick them up for execution.
- When the leaf tracing mode is enabled, leaf futures, instead of normal operation, call a special
trace_leaf()function that will capture the backtrace usingbacktracecrate up until the task root.
Leaf futures are almost always are tokio primitives like timers, channels, IO or locks. All these leaf futures have trace_leaf() call when tokio_taskdump feature is enabled.
If you have some custom future as a leaf that doesn't call into tokio, you most likely won't see the backtrace for the task that awaits on this future in the taskdump.
- Individual backtraces for each leaf future are then collected and transformed into a tree, joining common ancestors into a single node. This gives a nice tree view as show below, where you can easily spot concurrent primitives like
select!andFuturesUnordered.
Let's integrate it into our example application and see what our task future trees look like when dumped. We'll trigger the dump in the SIGINT handler task right after we receive the first signal.
// start SIGINT handler
let signal_task = tokio::spawn(async move {
ctrl_c().await.unwrap();
println!("Received Ctrl-C first time...");
// Inside an async block or function.
let handle = tokio::runtime::Handle::current();
if let Ok(dump) = tokio::time::timeout(std::time::Duration::from_secs(2), handle.dump()).await {
for (i, task) in dump.tasks().iter().enumerate() {
let trace = task.trace();
println!("TASK {i}:");
println!("{trace}\n");
}
}
ctrl_c().await.unwrap();
println!("Received Ctrl-C once again, exiting...");
});
We then need to build the application with tokio_unstable and tokio_taskdump flags (on older tokio versions, it's just tokio_unstable):
RUSTFLAGS="--cfg tokio_unstable --cfg tokio_taskdump"
When we press ^C, we'll see the following output:
TASK 0:
TASK 1:
╼ stuck_task_example::main::{{closure}}::{{closure}} at /home/alexey/Dev/lab/gdb-tokio-tasks/stuck-task-example/src/main.rs:31:98
├╼ <tokio::time::timeout::Timeout<T> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/timeout.rs:202:42
│ └╼ tokio::runtime::handle::Handle::dump::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/handle.rs:579:24
│ └╼ tokio::runtime::handle::spawn_thread::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/handle.rs:607:16
│ └╼ <tokio::sync::oneshot::Receiver<T> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/oneshot.rs:1252:64
│ └╼ tokio::sync::oneshot::Inner<T>::poll_recv at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/oneshot.rs:1286:16
└╼ <tokio::time::timeout::Timeout<T> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/timeout.rs:225:13
└╼ <tokio::time::timeout::Timeout<T> as core::future::future::Future>::poll::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/timeout.rs:211:25
└╼ <tokio::time::sleep::Sleep as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/sleep.rs:446:36
└╼ tokio::time::sleep::Sleep::poll_elapsed at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/sleep.rs:402:16
TASK 2:
╼ stuck_task_example::main::{{closure}}::{{closure}} at /home/alexey/Dev/lab/gdb-tokio-tasks/stuck-task-example/src/main.rs:49:13
└╼ <core::future::poll_fn::PollFn<F> as core::future::future::Future>::poll at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/poll_fn.rs:151:9
├╼ stuck_task_example::main::{{closure}}::{{closure}}::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/macros/select.rs:708:49
│ └╼ tokio::time::interval::Interval::tick::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/interval.rs:447:17
│ └╼ <tokio::util::trace::InstrumentedAsyncOp<F> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/util/trace.rs:162:57
│ └╼ <core::future::poll_fn::PollFn<F> as core::future::future::Future>::poll at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/poll_fn.rs:151:9
│ └╼ tokio::time::interval::Interval::tick::{{closure}}::{{closure}}::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/interval.rs:438:34
│ └╼ tokio::time::interval::Interval::poll_tick at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/interval.rs:464:42
│ └╼ <core::pin::Pin<P> as core::future::future::Future>::poll at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:133:9
│ └╼ <tokio::time::sleep::Sleep as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/sleep.rs:446:36
│ └╼ tokio::time::sleep::Sleep::poll_elapsed at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/sleep.rs:402:16
└╼ stuck_task_example::main::{{closure}}::{{closure}}::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/macros/select.rs:708:49
└╼ tokio::time::interval::Interval::tick::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/interval.rs:447:17
└╼ <tokio::util::trace::InstrumentedAsyncOp<F> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/util/trace.rs:162:57
└╼ <core::future::poll_fn::PollFn<F> as core::future::future::Future>::poll at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/poll_fn.rs:151:9
└╼ tokio::time::interval::Interval::tick::{{closure}}::{{closure}}::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/interval.rs:438:34
└╼ tokio::time::interval::Interval::poll_tick at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/interval.rs:464:42
└╼ <core::pin::Pin<P> as core::future::future::Future>::poll at /home/alexey/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:133:9
└╼ <tokio::time::sleep::Sleep as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/sleep.rs:446:36
└╼ tokio::time::sleep::Sleep::poll_elapsed at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/time/sleep.rs:402:16
TASK 3:
╼ stuck_task_example::main::{{closure}}::{{closure}} at /home/alexey/Dev/lab/gdb-tokio-tasks/stuck-task-example/src/main.rs:71:37
└╼ tokio::sync::mutex::Mutex<T>::lock::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/mutex.rs:455:33
└╼ <tokio::util::trace::InstrumentedAsyncOp<F> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/util/trace.rs:162:57
└╼ tokio::sync::mutex::Mutex<T>::lock::{{closure}}::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/mutex.rs:436:28
└╼ tokio::sync::mutex::Mutex<T>::acquire::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/mutex.rs:654:27
└╼ <tokio::sync::batch_semaphore::Acquire as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/batch_semaphore.rs:579:16
TASK 4:
╼ stuck_task_example::main::{{closure}}::{{closure}} at /home/alexey/Dev/lab/gdb-tokio-tasks/stuck-task-example/src/main.rs:79:37
└╼ tokio::sync::mutex::Mutex<T>::lock::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/mutex.rs:455:33
└╼ <tokio::util::trace::InstrumentedAsyncOp<F> as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/util/trace.rs:162:57
└╼ tokio::sync::mutex::Mutex<T>::lock::{{closure}}::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/mutex.rs:436:28
└╼ tokio::sync::mutex::Mutex<T>::acquire::{{closure}} at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/mutex.rs:654:27
└╼ <tokio::sync::batch_semaphore::Acquire as core::future::future::Future>::poll at /home/alexey/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/sync/batch_semaphore.rs:579:16
TASK 0which should have been our TCP server task, didn't get a backtrace for some reason. I haven't dug into it, but it is probably due to missingtrace_leafinstrumentation.TASK 1is theSIGINThandler task. Since we reused it for the taskdump, we don’t actually see any signal handling futures here.TASK 2is theselect!task. You can see theselect!as two different subtrees of interval timer futures.TASK 3andTASK 4are tasks deadlocked on a pair of mutexes.
Can be used for:
- Getting pretty async backtraces!
- Probably for anything where a backtrace can help, e.g. tracking deadlocks or stuck tasks.
Can not be used for:
- Anything else.
Notes and caveats:
Target application needs to be modified so it calls
dump()when triggered.Target application needs to be compiled with debuginfo, or have split debuginfo file available alongside the binary.
backtrace-rshas been able to load split debuginfo files perfectly fine since 2021 ([ 3 ]). I'd overlooked this initially, which is why I've almost never used this feature in production.Even though split debuginfo is supported, it still has to be available on the target machine, which can be a problem for e.g. embedded devices.
4.3 async-backtrace / await-tree
async-backtrace repository: github.com/tokio-rs/async-backtrace
await-tree repository: github.com/risingwavelabs/await-tree
These two crates explore similar ideas and rely on manual code annotations. I haven’t seen either one gaining much traction lately, and personally, I'm not a fan of this approach, but let's explore it out of curiosity.
Here's what a dump from our example application looks like after we annotate the top-level task futures:
Tasks:
╼ stuck_task_example::main::{{closure}} at src/main.rs:66:18
╼ stuck_task_example::main::{{closure}} at src/main.rs:59:9
╼ stuck_task_example::main::{{closure}} at src/main.rs:35:18
╼ stuck_task_example::main::{{closure}} at src/main.rs:24:36
╼ stuck_task_example::main::{{closure}} at src/main.rs:12:22
The information is limited to futures you've manually annotated.
Can be used for:
- Getting concise async backtrace for user-instrumented code.
Can not be used for:
- Anything else.
Notes and caveats:
- Requires manual annotation. Scope is limited to annotated code.
4.4 Bug-stalker (rust-first debugger)
Homepage: godzie44.github.io/BugStalker/
This is one of the most promising attempts at a Rust-first debuggers. It supports basic debugger functionality along with std pretty‑printers and tokio observability. One feature I personally like is using std::fmt::Debug to print debuggee values.
Unfortunately, something seems broken with symbol resolution and/or backtrace capture in the current version (0.35), at least on my machine, so I couldn't test it on the example app. Listing it here for visibility anyway.