Tools and Guidelines for troubleshooting hanging futures

[gftea]

Hi, in a complex system, I encounter some futures are never scheduled, and would need suggestion how to troubleshoot such issue.
I simply narrow down to below context

• Sender side, it wait forever at sending a message over the bounded channel
• Reciever side is a async task which run a loop with tokio::select!, which hold the receiver, and this loop seems never scheduled, because sender await is not returning

I wonder if there is tools or guide how to troubleshoot such issue

[Darksonn]

I've heard people ask for help with very similar symptoms before, and the most common cause is that some task on the runtime is blocking the thread. You can diagnose this using Tokio console by looking for tasks where:

1. The busy duration keeps going up.
2. But the poll counter does not change.

If you have a task like that, then that is probably the cause.

[gftea]

@Darksonn , to understand further, when the thread is blocked, the tasks on per-thread queue will not be able to scheduled or stealed. In my case, while this happen, most thread is idle, and I wonder if there is way to trace which async tasks currently allocated on which thread?

[Darksonn]

The easiest way to check which task a thread is stuck in is to use gdb to get a stack trace.

[gftea]

@Darksonn, thanks for the hint, just I can only see limited info from stacktrace of threads,
Any hint to inspect task list in a thread?

(lldb) thread backtrace all
  thread #1, name = 'main', queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x000000019fb02f40 libsystem_kernel.dylib`kevent + 8
    frame #1: 0x000000010131aaec rpc_node`mio::poll::Poll::poll::hc3df278bc45078cb + 116
    frame #2: 0x0000000101301e78 rpc_node`tokio::runtime::io::driver::Driver::turn::h16195940ba3ed0b3 + 348
    frame #3: 0x00000001012e7fe0 rpc_node`tokio::runtime::time::Driver::park_internal::h33b9694c3e0a721e + 1040
    frame #4: 0x00000001012f40ac rpc_node`tokio::runtime::scheduler::current_thread::Context::park::h72cc45894d45aa59 + 552
    frame #5: 0x000000010028d354 rpc_node`ntex_rt::tokio::block_on::h2750c87a7f47a9de + 3088
    frame #6: 0x00000001002b228c rpc_node`rpc_node::main::h5f6e55eed5936d2d + 368
    frame #7: 0x000000010031b7cc rpc_node`std::sys_common::backtrace::__rust_begin_short_backtrace::h0d38442a56a50e91 + 12
    frame #8: 0x00000001002c1bd0 rpc_node`std::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::h2abdbee15555398e + 28
    frame #9: 0x00000001015ba344 rpc_node`std::rt::lang_start_internal::hd3ad173a069f2ae5 + 640
    frame #10: 0x00000001002b2404 rpc_node`main + 52
    frame #11: 0x000000019f7b3154 dyld`start + 2476
  thread #2, name = 'tokio-runtime-worker'
    frame #0: 0x000000019fb005ec libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x000000019fb3e55c libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x000000010131c738 rpc_node`parking_lot::condvar::Condvar::wait_until_internal::ha0be1b58904d0b8e + 856
    frame #3: 0x00000001012ffa70 rpc_node`tokio::runtime::blocking::pool::Inner::run::hfde6a841ad1008da + 380
    frame #4: 0x00000001012e82b8 rpc_node`std::sys_common::backtrace::__rust_begin_short_backtrace::h2646e1ff3eea7533 + 188
    frame #5: 0x00000001012fb494 rpc_node`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hb783a8c3ca628fe9 + 164
    frame #6: 0x00000001015c9494 rpc_node`std::sys::pal::unix::thread::Thread::new::thread_start::h9e081ad7dac4e4c5 + 52
    frame #7: 0x000000019fb3df94 libsystem_pthread.dylib`_pthread_start + 136
  thread #3
    frame #0: 0x000000019fb005ec libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x000000019fb3e55c libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x0000000101520028 rpc_node`std::sync::condvar::Condvar::wait::h1647b694548978ba + 176
    frame #3: 0x000000010165f788 rpc_node`rayon_core::sleep::Sleep::sleep::h67f17fc9b894e7cd + 640
    frame #4: 0x000000010165f020 rpc_node`rayon_core::registry::WorkerThread::wait_until_cold::h8bb2b3ede772b464 + 180
    frame #5: 0x000000010151cec4 rpc_node`rayon_core::registry::ThreadBuilder::run::h2a97b7fefe541f95 + 196
    frame #6: 0x0000000101520adc rpc_node`std::sys_common::backtrace::__rust_begin_short_backtrace::h81750abb04dfa669 + 52
    frame #7: 0x00000001015228b4 rpc_node`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h518973ea266e6131 + 224
    frame #8: 0x00000001015c9494 rpc_node`std::sys::pal::unix::thread::Thread::new::thread_start::h9e081ad7dac4e4c5 + 52
    frame #9: 0x000000019fb3df94 libsystem_pthread.dylib`_pthread_start + 136
  thread #4
    frame #0: 0x000000019fb005ec libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x000000019fb3e55c libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x0000000101520028 rpc_node`std::sync::condvar::Condvar::wait::h1647b694548978ba + 176
    frame #3: 0x000000010165f788 rpc_node`rayon_core::sleep::Sleep::sleep::h67f17fc9b894e7cd + 640
    frame #4: 0x000000010165f020 rpc_node`rayon_core::registry::WorkerThread::wait_until_cold::h8bb2b3ede772b464 + 180
    frame #5: 0x000000010151cec4 rpc_node`rayon_core::registry::ThreadBuilder::run::h2a97b7fefe541f95 + 196
    frame #6: 0x0000000101520adc rpc_node`std::sys_common::backtrace::__rust_begin_short_backtrace::h81750abb04dfa669 + 52
    frame #7: 0x00000001015228b4 rpc_node`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h518973ea266e6131 + 224
    frame #8: 0x00000001015c9494 rpc_node`std::sys::pal::unix::thread::Thread::new::thread_start::h9e081ad7dac4e4c5 + 52
    frame #9: 0x000000019fb3df94 libsystem_pthread.dylib`_pthread_start + 136
  thread #5
    frame #0: 0x000000019fb005ec libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x000000019fb3e55c libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x0000000101520028 rpc_node`std::sync::condvar::Condvar::wait::h1647b694548978ba + 176
    frame #3: 0x000000010165f788 rpc_node`rayon_core::sleep::Sleep::sleep::h67f17fc9b894e7cd + 640
    frame #4: 0x000000010165f020 rpc_node`rayon_core::registry::WorkerThread::wait_until_cold::h8bb2b3ede772b464 + 180
    frame #5: 0x000000010151cec4 rpc_node`rayon_core::registry::ThreadBuilder::run::h2a97b7fefe541f95 + 196
    frame #6: 0x0000000101520adc rpc_node`std::sys_common::backtrace::__rust_begin_short_backtrace::h81750abb04dfa669 + 52
    frame #7: 0x00000001015228b4 rpc_node`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h518973ea266e6131 + 224
    frame #8: 0x00000001015c9494 rpc_node`std::sys::pal::unix::thread::Thread::new::thread_start::h9e081ad7dac4e4c5 + 52
    frame #9: 0x000000019fb3df94 libsystem_pthread.dylib`_pthread_start + 136
* thread #6

[Darksonn]

It looks like the runtime is running on thread 1 and that it is idle. Thread 2 is a spawn_blocking thread that is also idle, and the other threads are part of rayon.

From this, it appears that you do not have a task that is blocking the thread. What is the task stuck on? If it's a custom future, then it may be implemented incorrectly.

[gftea]

OK, thanks @Darksonn , I think I got a answer to start with, will need to dig into further.