add feature to show mpsc channel metrics

[whitelilis]

The resource now only show semaphore and timer, it is very helpful to show channel metrics, such as how many message in/out/drop/still_in_channel.

[whitelilis]

Now can see oneshot channel， but can't see mpsc channel

[seanmonstar]

Yea, this is definitely desired. It'd mostly require instrumentation in the Tokio crate, and then the console would just "see it". Would you be interested in helping add this?

[oguzbilgener]

If @whitelilis doesn't call dibs I'd be willing to help with this.

[hawkw]

I believe @zaharidichev previously added instrumentation to the Tokio MPSC channels, but it had to be removed because the console-subscriber crate uses a MPSC internally, so it caused a deadlock. In order to put the MPSC instrumentation back, we'll need to find a workaround for this

[hawkw]

(the problem is specifically the register_callsite calls for the MPSC instrumentation causing the use of a MPSC channel. we could probably work around this by special casing those callsites to be sent separately, outside of the register_callsite call...)

[domodwyer]

Hi @hawkw,

I've been playing with this locally and have a working prototype that records various stats about an (un)bounded mpsc channel:

I've also run into the deadlock you describe when switching console-subscriber to use the tokio patched to emit the spans too. Two attempts are made to acquire the registry lock in tracing-core, before the code has a chance to call the register_callsite() in console-subscriber :(

I'm happy to try and push this forwards but I'm not sure how best work around this - any pointers? Below is the metadata for the mpsc captured in the tracing::MacroCallsite::interest() call that eventually deadlocks:

[/Users/dom/Documents/rust/tracing/tracing/src/lib.rs:1044] self = MacroCallsite {
    interest: 57005,
    meta: Metadata {
        name: "event /Users/dom/Documents/rust/tokio/tokio/src/sync/mpsc/chan.rs:212",
        target: "runtime::resource::state_update",
        level: Level(
            Trace,
        ),
        module_path: "tokio::sync::mpsc::chan",
        location: /Users/dom/Documents/rust/tokio/tokio/src/sync/mpsc/chan.rs:212,
        fields: {tx, tx.op},
        callsite: Identifier(0x1006eaa08),
        kind: Kind(EVENT),
    },
    registration: Once { .. },
}

[hawkw]

@domodowyer

I've also run into the deadlock you describe when switching console-subscriber to use the tokio patched to emit the spans too. Two attempts are made to acquire the registry lock in tracing-core, before the code has a chance to call the register_callsite() in console-subscriber :(

I'm working on an upstream change to fix this: tokio-rs/tracing#2020

If you have the time, it would be very helpful to try using a cargo patch to test the changes in that PR against your console branch, and make sure everything works.

[domodwyer]

Hi @hawkw,

I had a play around with the eliza/fix-register-deadlock branch, but unfortunately there is still a deadlock during init.

I have attached a full backtrace below, but it appears that while the Dispatch is being initialised (from ConsoleLayer::init()) it rebuilds the callsite interests while holding the mutex, and that eventually causes a register() call to deadlock on the same mutex:

1. ConsoleLayer::init()
2. tracing_subscriber::init() calls Dispatch::new()
3. Dispatch::new() calls callsite::register_dispatch() which obtains the registry lock
4. Calls rebuild_interest()
5. Which in turn, calls try_register
6. Which eventually causes console_subscriber::ConsoleLayer::register_callsite() to send on the mpsc
7. This mpsc is instrumented with a trace! and causes a call to event!, which in turn
8. Calls MacroCallsite::interest() -> register() -> try_register()
9. At this point, this is the first time this thread has hit try_register() and therefore IS_REGISTERING == false
10. This allows the thread to proceed into Callsite::register() and it deadlocks waiting for the lock held in bullet 3

Thanks for your work on this - I'm happy to help however I can 👍

Backtrace

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00000001bbec7758 libsystem_kernel.dylib`__psynch_mutexwait + 8
    frame #1: 0x00000001bbeff384 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84
    frame #2: 0x00000001bbefccf8 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 248
    frame #3: 0x0000000100faa1b4 tokio_test`std::sys::unix::mutex::Mutex::lock::hae04a88b43dd8c7e(self=0x00006000034e8040) at mutex.rs:63:17
    frame #4: 0x0000000100fa4fe8 tokio_test`std::sys_common::mutex::MovableMutex::raw_lock::h74348ea44b3067c4(self=0x00000001010dec08) at mutex.rs:76:18
    frame #5: 0x0000000100fafbf0 tokio_test`std::sync::mutex::Mutex$LT$T$GT$::lock::hc0c2165f7b568968(self=0x00000001010dec08) at mutex.rs:267:13
    frame #6: 0x0000000100fac818 tokio_test`tracing_core::mutex::imp::Mutex$LT$T$GT$::lock::h0eb83dbf5fee0d5c(self=0x00000001010dec08) at mutex.rs:17:19
    frame #7: 0x0000000100fa3ff8 tokio_test`tracing_core::callsite::register::h1b65a7643fa046c1(callsite=&dyn tracing_core::callsite::Callsite @ 0x000000016f455d80) at callsite.rs:137:24
    frame #8: 0x0000000100fa4120 tokio_test`tracing_core::callsite::try_register::_$u7b$$u7b$closure$u7d$$u7d$::h27b48fb45283ba4c(cell=0x0000000133e043ed) at callsite.rs:167:13
    frame #9: 0x0000000100fae908 tokio_test`std::thread::local::LocalKey$LT$T$GT$::try_with::h16be7b48628ae17c(self=0x00000001010d77b0, f={closure#0} @ 0x000000016f455e40) at local.rs:412:16
    frame #10: 0x0000000100fa40a4 tokio_test`tracing_core::callsite::try_register::ha757e2fe3dcf4903(callsite=&dyn tracing_core::callsite::Callsite @ 0x000000016f455e88) at callsite.rs:159:5
    frame #11: 0x0000000101009dd0 tokio_test`tracing::__macro_support::MacroCallsite::register::h2fb12c9b4b581f9c(self=0x00000001010ddc38) at lib.rs:1042:28
    frame #12: 0x0000000100acc6f0 tokio_test`tracing::__macro_support::MacroCallsite::interest::h324e61f83f4172e9(self=0x00000001010ddc38) at lib.rs:1096:22
    frame #13: 0x0000000100c219e0 tokio_test`tokio::sync::mpsc::chan::Tx$LT$T$C$S$GT$::send::_$u7b$$u7b$closure$u7d$$u7d$::h46c45f268888f6ba((null)={closure#0} @ 0x000000016f456b6f) at chan.rs:212:13
    frame #14: 0x0000000100ac948c tokio_test`tracing::span::Span::in_scope::he3c312aa6cf730fc(self=0x000000013401de88, f={closure#0} @ 0x000000016f456df7) at span.rs:1092:9
    frame #15: 0x0000000100c21550 tokio_test`tokio::sync::mpsc::chan::Tx$LT$T$C$S$GT$::send::h25ab86cfcd73b32d(self=0x000000013401de80, value=Event @ 0x000000016f456fd8) at chan.rs:211:9
    frame #16: 0x0000000100b17d98 tokio_test`tokio::sync::mpsc::bounded::Permit$LT$T$GT$::send::h836c817a336dc021(self=Permit<console_subscriber::Event> @ 0x000000016f456fd0, value=<unavailable>) at bounded.rs:1080:9
    frame #17: 0x0000000100ad29f8 tokio_test`console_subscriber::ConsoleLayer::send_stats::h2c31a46e947d8c5a(self=0x000000013401dc60, dropped=0x00006000002ecea8, mk_event={closure#0} @ 0x000000016f457680) at lib.rs:417:17
    frame #18: 0x0000000100ad2120 tokio_test`console_subscriber::ConsoleLayer::send_metadata::h837827be51b337b7(self=0x000000013401dc60, dropped=0x00006000002ecea8, event=<unavailable>) at lib.rs:402:9
    frame #19: 0x0000000100ad4bdc tokio_test`_$LT$console_subscriber..ConsoleLayer$u20$as$u20$tracing_subscriber..layer..Layer$LT$S$GT$$GT$::register_callsite::he3c7cae968fd0af9(self=0x000000013401dc60, meta=0x00000001010d3f58) at lib.rs:537:9
    frame #20: 0x0000000100bfd518 tokio_test`_$LT$tracing_subscriber..filter..layer_filters..Filtered$LT$L$C$F$C$S$GT$$u20$as$u20$tracing_subscriber..layer..Layer$LT$S$GT$$GT$::register_callsite::h3b24b3fc5400bf2c(self=0x000000013401dc50, metadata=0x00000001010d3f58) at mod.rs:537:13
    frame #21: 0x0000000100b5bc6c tokio_test`_$LT$tracing_subscriber..layer..layered..Layered$LT$L$C$S$GT$$u20$as$u20$tracing_core..subscriber..Subscriber$GT$::register_callsite::hc31f21c62fc4cc66(self=0x000000013401dc50, metadata=0x00000001010d3f58) at layered.rs:72:28
    frame #22: 0x0000000100b5bd78 tokio_test`_$LT$tracing_subscriber..layer..layered..Layered$LT$L$C$S$GT$$u20$as$u20$tracing_core..subscriber..Subscriber$GT$::register_callsite::_$u7b$$u7b$closure$u7d$$u7d$::h9b89107fe301f01c at layered.rs:73:13
    frame #23: 0x0000000100b5d194 tokio_test`tracing_subscriber::layer::layered::Layered$LT$A$C$B$C$S$GT$::pick_interest::h8fb416091ea9f4f8(self=0x000000013401dc10, outer=Interest @ 0x000000016f457b03, inner={closure#0} @ 0x000000016f457b10) at layered.rs:379:20
    frame #24: 0x0000000100b5bcf8 tokio_test`_$LT$tracing_subscriber..layer..layered..Layered$LT$L$C$S$GT$$u20$as$u20$tracing_core..subscriber..Subscriber$GT$::register_callsite::hd3cfac027f30a835(self=0x000000013401dc10, metadata=0x00000001010d3f58) at layered.rs:72:9
    frame #25: 0x0000000100fa57a4 tokio_test`_$LT$alloc..sync..Arc$LT$dyn$u20$tracing_core..subscriber..Subscriber$u2b$core..marker..Send$u2b$core..marker..Sync$GT$$u20$as$u20$tracing_core..subscriber..Subscriber$GT$::register_callsite::hbea1a0cfc1eda772(self=0x000000016f457bd8, metadata=0x00000001010d3f58) at subscriber.rs:678:9
    frame #26: 0x0000000100fae37c tokio_test`tracing_core::dispatcher::Registrar::try_register::_$u7b$$u7b$closure$u7d$$u7d$::h88953d86462adf2f(s=strong=2, weak=1) at dispatcher.rs:665:34
    frame #27: 0x0000000100fa7f90 tokio_test`core::option::Option$LT$T$GT$::map::hb587363cf2b424e9(self=Option<alloc::sync::Arc<(dyn tracing_core::subscriber::Subscriber + core::marker::Send + core::marker::Sync)>> @ 0x000000016f457c28, f={closure#0} @ 0x000000016f457c58) at option.rs:883:29
    frame #28: 0x0000000100fae33c tokio_test`tracing_core::dispatcher::Registrar::try_register::hb199cd49a0aaae61(self=0x00006000034e8090, metadata=0x00000001010d3f58) at dispatcher.rs:665:9
    frame #29: 0x0000000100fa3cf8 tokio_test`tracing_core::callsite::Registry::rebuild_callsite_interest::_$u7b$$u7b$closure$u7d$$u7d$::h2ed1b79486c070ef(registrar=0x00006000034e8090) at callsite.rs:36:37
    frame #30: 0x0000000100fb3864 tokio_test`core::iter::adapters::filter_map::filter_map_fold::_$u7b$$u7b$closure$u7d$$u7d$::haafa3a9053ae20f4(acc=Interest @ 0x000000016f457d2f, item=0x00006000034e8090) at filter_map.rs:36:28
    frame #31: 0x0000000100fabb28 tokio_test`core::iter::traits::iterator::Iterator::fold::h15321b63b64f3c1c(self=Iter<tracing_core::dispatcher::Registrar> @ 0x000000016f457d78, init=Interest @ 0x000000016f457db7, f={closure#0} @ 0x000000016f457d88) at iterator.rs:2171:21
    frame #32: 0x0000000100fb39ac tokio_test`_$LT$core..iter..adapters..filter_map..FilterMap$LT$I$C$F$GT$$u20$as$u20$core..iter..traits..iterator..Iterator$GT$::fold::h580c2fd755eb00ae(self=<unavailable>, init=Interest @ 0x000000016f457e0e, fold=0x000000034e80a000) at filter_map.rs:85:9
    frame #33: 0x0000000100fa3c98 tokio_test`tracing_core::callsite::Registry::rebuild_callsite_interest::hadc923e178133f10(self=0x00000001010dec18, callsite=&dyn tracing_core::callsite::Callsite @ 0x000000016f457ec8) at callsite.rs:41:13
    frame #34: 0x0000000100fa3fb8 tokio_test`tracing_core::callsite::Registry::rebuild_interest::_$u7b$$u7b$closure$u7d$$u7d$::h94c1c4d6065e7cb2((null)=0x0000600000fe8100) at callsite.rs:67:13
    frame #35: 0x0000000100fac508 tokio_test`_$LT$core..slice..iter..Iter$LT$T$GT$$u20$as$u20$core..iter..traits..iterator..Iterator$GT$::for_each::h32e124b693b1409a(self=Iter<&dyn tracing_core::callsite::Callsite> @ 0x000000016f457f30, f={closure#1} @ 0x000000016f457f40) at macros.rs:211:21
    frame #36: 0x0000000100fa3d78 tokio_test`tracing_core::callsite::Registry::rebuild_interest::h83ad1fd7d8e21003(self=0x00000001010dec18) at callsite.rs:66:9
    frame #37: 0x0000000100fa41f8 tokio_test`tracing_core::callsite::register_dispatch::h3b15f0defad1b918(dispatch=0x000000016f458058) at callsite.rs:208:5
    frame #38: 0x0000000100abc340 tokio_test`tracing_core::dispatcher::Dispatch::new::he4d559e3d4c92c3c(subscriber=<unavailable>) at dispatcher.rs:417:9
    frame #39: 0x0000000100abcf94 tokio_test`_$LT$tracing_core..dispatcher..Dispatch$u20$as$u20$core..convert..From$LT$S$GT$$GT$::from::h6a5cf675618f5fb9(subscriber=<unavailable>) at dispatcher.rs:656:9
    frame #40: 0x0000000100b68814 tokio_test`_$LT$T$u20$as$u20$core..convert..Into$LT$U$GT$$GT$::into::he7ac54d6c19bcdc9(self=<unavailable>) at mod.rs:543:9
    frame #41: 0x0000000100b5d69c tokio_test`tracing_subscriber::util::SubscriberInitExt::try_init::h407f0cbff58d6a6c(self=<unavailable>) at util.rs:59:40
    frame #42: 0x0000000100b5d76c tokio_test`tracing_subscriber::util::SubscriberInitExt::init::h2f53ca42fae37668(self=<unavailable>) at util.rs:90:9
    frame #43: 0x0000000100a225b4 tokio_test`console_subscriber::builder::Builder::init::h3694b3f5245bdccd(self=Builder @ 0x000000016f460110) at builder.rs:306:9
    frame #44: 0x0000000100a23118 tokio_test`console_subscriber::builder::init::h857cfe70dc4e0710 at builder.rs:484:5
    frame #45: 0x00000001009d8f48 tokio_test`tokio_test::main::_$u7b$$u7b$closure$u7d$$u7d$::h45c97020794e1835((null)=ResumeTy @ 0x000000016f460a08) at main.rs:5:5
    frame #46: 0x00000001009c52d4 tokio_test`_$LT$core..future..from_generator..GenFuture$LT$T$GT$$u20$as$u20$core..future..future..Future$GT$::poll::hfb4467776524a8b7(self=Pin<&mut core::future::from_generator::GenFuture<tokio_test::main::{generator#0}>> @ 0x000000016f460b20, cx=0x000000016f461120) at mod.rs:84:19
    frame #47: 0x00000001009ce7a4 tokio_test`_$LT$tracing..instrument..Instrumented$LT$T$GT$$u20$as$u20$core..future..future..Future$GT$::poll::h3a64bd227517b3fd(self=Pin<&mut tracing::instrument::Instrumented<core::future::from_generator::GenFuture<tokio_test::main::{generator#0}>>> @ 0x000000016f460b88, cx=0x000000016f461120) at instrument.rs:272:9
    frame #48: 0x00000001009d30e4 tokio_test`_$LT$core..pin..Pin$LT$P$GT$$u20$as$u20$core..future..future..Future$GT$::poll::hf70156d688e1cba0(self=Pin<&mut core::pin::Pin<&mut tracing::instrument::Instrumented<core::future::from_generator::GenFuture<tokio_test::main::{generator#0}>>>> @ 0x000000016f460c98, cx=0x000000016f461120) at future.rs:123:9
    frame #49: 0x00000001009d5274 tokio_test`tokio::runtime::basic_scheduler::CoreGuard::block_on::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h85b2b9ceacdff1bf at basic_scheduler.rs:498:48
    frame #50: 0x00000001009c5544 tokio_test`tokio::coop::with_budget::_$u7b$$u7b$closure$u7d$$u7d$::h484c976f296b862e(cell=0x0000000133e043ea) at coop.rs:102:9
    frame #51: 0x00000001009c6988 tokio_test`std::thread::local::LocalKey$LT$T$GT$::try_with::h737b577cef60d6e0(self=0x00000001010a4c48, f={closure#0} @ 0x000000016f460e60) at local.rs:412:16
    frame #52: 0x00000001009c6654 tokio_test`std::thread::local::LocalKey$LT$T$GT$::with::h8abcbe48049942c0(self=0x00000001010a4c48, f=<unavailable>) at local.rs:388:9
    frame #53: 0x00000001009d51f0 tokio_test`tokio::runtime::basic_scheduler::CoreGuard::block_on::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h472ee4031aef965b [inlined] tokio::coop::with_budget::ha0429b8782e3a0a4(budget=Budget @ 0x000000016f460f1e, f={closure#0} @ 0x000000016f460f20) at coop.rs:95:5
    frame #54: 0x00000001009d51cc tokio_test`tokio::runtime::basic_scheduler::CoreGuard::block_on::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h472ee4031aef965b [inlined] tokio::coop::budget::hf3af79c6c28f53d3(f={closure#0} @ 0x000000016f460ee0) at coop.rs:72:5
    frame #55: 0x00000001009d5180 tokio_test`tokio::runtime::basic_scheduler::CoreGuard::block_on::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h472ee4031aef965b at basic_scheduler.rs:498:25
    frame #56: 0x00000001009d44fc tokio_test`tokio::runtime::basic_scheduler::Context::enter::h58fc6e1b3165e019(self=0x000000016f4613d0, core=0x0000000133e04d00, f={closure#0} @ 0x000000016f460ff8) at basic_scheduler.rs:356:19
    frame #57: 0x00000001009d4e14 tokio_test`tokio::runtime::basic_scheduler::CoreGuard::block_on::_$u7b$$u7b$closure$u7d$$u7d$::heef3ff706f756aa0(core=0x0000000133e04d00, context=0x000000016f4613d0) at basic_scheduler.rs:497:36
    frame #58: 0x00000001009d55e8 tokio_test`tokio::runtime::basic_scheduler::CoreGuard::enter::_$u7b$$u7b$closure$u7d$$u7d$::h9c5e823fe6f651ae at basic_scheduler.rs:555:57
    frame #59: 0x00000001009c3e8c tokio_test`tokio::macros::scoped_tls::ScopedKey$LT$T$GT$::set::hbd8809012f0ba19c(self=0x00000001010d3418, t=0x000000016f4613d0, f={closure#0} @ 0x000000016f461370) at scoped_tls.rs:61:9
    frame #60: 0x00000001009d5430 tokio_test`tokio::runtime::basic_scheduler::CoreGuard::enter::h0ad4fbe7e420fb4b(self=CoreGuard @ 0x000000016f4613d0, f={closure#0} @ 0x000000016f4613a8) at basic_scheduler.rs:555:27
    frame #61: 0x00000001009d4c8c tokio_test`tokio::runtime::basic_scheduler::CoreGuard::block_on::h4df42a278777eec0(self=<unavailable>, future=Pin<&mut tracing::instrument::Instrumented<core::future::from_generator::GenFuture<tokio_test::main::{generator#0}>>> @ 0x000000016f4613f8) at basic_scheduler.rs:488:9
    frame #62: 0x00000001009d3f08 tokio_test`tokio::runtime::basic_scheduler::BasicScheduler::block_on::h9991b809627a4ce2(self=0x000000016f462420, future=<unavailable>) at basic_scheduler.rs:168:24
    frame #63: 0x00000001009d7174 tokio_test`tokio::runtime::Runtime::block_on::hdc8e4a3b52911b24(self=0x000000016f462418, future=<unavailable>) at mod.rs:479:46
    frame #64: 0x00000001009d8e6c tokio_test`tokio_test::main::h51c77516b95bc3c6 at main.rs:13:5
    frame #65: 0x00000001009d78ac tokio_test`core::ops::function::FnOnce::call_once::h6455b60309d1542e((null)=(tokio_test`tokio_test::main::h51c77516b95bc3c6 at main.rs:4), (null)=<unavailable>) at function.rs:227:5
    frame #66: 0x00000001009c4a1c tokio_test`std::sys_common::backtrace::__rust_begin_short_backtrace::h7f1d5a9536ed1d4d(f=(tokio_test`tokio_test::main::h51c77516b95bc3c6 at main.rs:4)) at backtrace.rs:123:18
    frame #67: 0x00000001009cf614 tokio_test`std::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::hae1b8c612bc0312d at rt.rs:145:18
    frame #68: 0x0000000100fe2100 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] core::ops::function::impls::_$LT$impl$u20$core..ops..function..FnOnce$LT$A$GT$$u20$for$u20$$RF$F$GT$::call_once::hba09dfad0460fd87 at function.rs:259:13 [opt]
    frame #69: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::panicking::try::do_call::h4ce3f7a5c9aef539 at panicking.rs:406:40 [opt]
    frame #70: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::panicking::try::hd24b5077d4e7cf4f at panicking.rs:370:19 [opt]
    frame #71: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::panic::catch_unwind::h7e4545d59021a7e8 at panic.rs:133:14 [opt]
    frame #72: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::rt::lang_start_internal::_$u7b$$u7b$closure$u7d$$u7d$::h84dbc49308bdb431 at rt.rs:128:48 [opt]
    frame #73: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::panicking::try::do_call::h72e6b5f705f91e0a at panicking.rs:406:40 [opt]
    frame #74: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::panicking::try::hb85264d1d4244b1a at panicking.rs:370:19 [opt]
    frame #75: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 [inlined] std::panic::catch_unwind::h202929673dde26bb at panic.rs:133:14 [opt]
    frame #76: 0x0000000100fe20f4 tokio_test`std::rt::lang_start_internal::h0c28bd035905a2f7 at rt.rs:128:20 [opt]
    frame #77: 0x00000001009cf5e0 tokio_test`std::rt::lang_start::hc8640376790455f1(main=(tokio_test`tokio_test::main::h51c77516b95bc3c6 at main.rs:4), argc=1, argv=0x000000016f462c60) at rt.rs:144:17
    frame #78: 0x00000001009da060 tokio_test`main + 32
    frame #79: 0x0000000101d31088 dyld`start + 516

[domodwyer]

I've pushed my tokio instrumentation changes and pre-emptively opened a PR, using that branch gives us a simple reproducer:

use std::time::Duration;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    console_subscriber::init();

    tokio::spawn(async {
        tokio::time::sleep(Duration::from_secs(100000)).await;
    });
}

and a patch in the Cargo.toml file to use the mpsc-instrumented tokio:

[patch.crates-io]
tokio = { git = "https://github.com/domodwyer/tokio", branch = "dom/trace-mpsc" }

The deadlock should be reproducible with a simple cargo run resulting in a similar backtrace as above, and attaching the console fails.

I hope this helps - I took a look at the code but I'm not familiar enough with the tracing internals to come up with a nice solution, but I'm happy to help however I can 👍