Capture backtraces for mutex dependencies

[bertptrs]

Builds on top of #28.

This PR adds backtrace data to the dependency graph, so you can figure out what series of events might have introduced the cycle in dependencies. Only the first backtrace

These changes do have a performance penalty, with a worst case of 20-50% degradation over previous results. This applies to the worst case scenario where every dependency between mutexes is new and thus is unlikely to be as severe.

Below is an example of what this can look like, generated with examples/mutex_cycle.rs. The formatting is decidedly suboptimal but backtraces cannot be formatted very well in stable rust at the moment. The exact performance hit depends on a lot of things, such as the level of backtraces captured (off, 1, or full), and how many dependencies are involved.

thread 'main' panicked at 'Found cycle in mutex dependency graph:
   0: tracing_mutex::MutexDep::capture
             at ./src/lib.rs:278:23
   1: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
   2: tracing_mutex::graph::DiGraph<V,E>::add_edge
             at ./src/graph.rs:131:50
   3: tracing_mutex::MutexId::mark_held::{{closure}}
             at ./src/lib.rs:146:17
   4: std::thread::local::LocalKey<T>::try_with
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/thread/local.rs:270:16
   5: std::thread::local::LocalKey<T>::with
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/thread/local.rs:246:9
   6: tracing_mutex::MutexId::mark_held
             at ./src/lib.rs:142:25
   7: tracing_mutex::MutexId::get_borrowed
             at ./src/lib.rs:129:9
   8: tracing_mutex::stdsync::tracing::Mutex<T>::lock
             at ./src/stdsync.rs:110:25
   9: mutex_cycle::main
             at ./examples/mutex_cycle.rs:20:18
  10: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
  11: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:135:18
  12: std::rt::lang_start::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:166:18
  13: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:284:13
  14: std::panicking::try::do_call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:500:40
  15: std::panicking::try
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:464:19
  16: std::panic::catch_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panic.rs:142:14
  17: std::rt::lang_start_internal::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:148:48
  18: std::panicking::try::do_call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:500:40
  19: std::panicking::try
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:464:19
  20: std::panic::catch_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panic.rs:142:14
  21: std::rt::lang_start_internal
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:148:20
  22: std::rt::lang_start
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:165:17
  23: main
  24: <unknown>
  25: __libc_start_main
  26: _start

   0: tracing_mutex::MutexDep::capture
             at ./src/lib.rs:278:23
   1: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
   2: tracing_mutex::graph::DiGraph<V,E>::add_edge
             at ./src/graph.rs:131:50
   3: tracing_mutex::MutexId::mark_held::{{closure}}
             at ./src/lib.rs:146:17
   4: std::thread::local::LocalKey<T>::try_with
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/thread/local.rs:270:16
   5: std::thread::local::LocalKey<T>::with
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/thread/local.rs:246:9
   6: tracing_mutex::MutexId::mark_held
             at ./src/lib.rs:142:25
   7: tracing_mutex::MutexId::get_borrowed
             at ./src/lib.rs:129:9
   8: tracing_mutex::stdsync::tracing::Mutex<T>::lock
             at ./src/stdsync.rs:110:25
   9: mutex_cycle::main
             at ./examples/mutex_cycle.rs:14:18
  10: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
  11: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:135:18
  12: std::rt::lang_start::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:166:18
  13: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:284:13
  14: std::panicking::try::do_call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:500:40
  15: std::panicking::try
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:464:19
  16: std::panic::catch_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panic.rs:142:14
  17: std::rt::lang_start_internal::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:148:48
  18: std::panicking::try::do_call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:500:40
  19: std::panicking::try
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:464:19
  20: std::panic::catch_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panic.rs:142:14
  21: std::rt::lang_start_internal
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:148:20
  22: std::rt::lang_start
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/rt.rs:165:17
  23: main
  24: <unknown>
  25: __libc_start_main
  26: _start

', src/lib.rs:163:13
stack backtrace:
   0: rust_begin_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:593:5
   1: core::panicking::panic_fmt
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:67:14
   2: tracing_mutex::MutexId::mark_held
             at ./src/lib.rs:163:13
   3: tracing_mutex::MutexId::get_borrowed
             at ./src/lib.rs:129:9
   4: tracing_mutex::stdsync::tracing::Mutex<T>::lock
             at ./src/stdsync.rs:110:25
   5: mutex_cycle::main
             at ./examples/mutex_cycle.rs:25:14
   6: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5

Importantly, the error shows all the dependencies that are already part of the graph, not the one that was just added, since that is already visible from the immediate panic.

[bertptrs]

@tbodt FYI I continued your work.

[bertptrs]

Capturing backtraces results in about 60% overhead, which isn't great, but without the backtraces feature the difference is well within the noise threshold, so I think it should be fine to merge like this.

bors r+

[bors]

Build succeeded!

The publicly hosted instance of bors-ng is deprecated and will go away soon.

If you want to self-host your own instance, instructions are here.
For more help, visit the forum.

If you want to switch to GitHub's built-in merge queue, visit their help page.

• Documentation build
• Rust project (1.70)
• Rust project (beta)
• Rust project (stable)