Merge #32

32: Capture backtraces for mutex dependencies r=bertptrs a=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. Co-authored-by: Bert Peters <bert@bertptrs.nl>
bertptrs · Sep 9, 2023 · d8c559f · d8c559f
2 parents 0ae544a + a8e8af6
commit d8c559f
Show file tree

Hide file tree

Showing 7 changed files with 198 additions and 59 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -11,6 +11,7 @@ adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 - The minimum supported Rust version is now defined as 1.70. Previously it was undefined.
 - Wrappers for `std::sync` primitives can now be `const` constructed.
 - Add support for `std::sync::OnceLock`
+- Added backtraces of mutex allocations to the cycle report. 
 
 ### Breaking
 

diff --git a/Cargo.toml b/Cargo.toml
@@ -31,6 +31,8 @@ name = "mutex"
 harness = false
 
 [features]
+default = ["backtraces"]
+backtraces = []
 # Feature names do not match crate names pending namespaced features.
 lockapi = ["lock_api"]
 parkinglot = ["parking_lot", "lockapi"]
diff --git a/examples/mutex_cycle.rs b/examples/mutex_cycle.rs
@@ -0,0 +1,26 @@
+//! Show what a crash looks like
+//!
+//! This shows what a traceback of a cycle detection looks like. It is expected to crash.
+use tracing_mutex::stdsync::Mutex;
+
+fn main() {
+    let a = Mutex::new(());
+    let b = Mutex::new(());
+    let c = Mutex::new(());
+
+    // Create an edge from a to b
+    {
+        let _a = a.lock();
+        let _b = b.lock();
+    }
+
+    // Create an edge from b to c
+    {
+        let _b = b.lock();
+        let _c = c.lock();
+    }
+
+    // Now crash by trying to add an edge from c to a
+    let _c = c.lock();
+    let _a = a.lock(); // This line will crash
+}
diff --git a/src/graph.rs b/src/graph.rs
@@ -1,4 +1,5 @@
 use std::cell::Cell;
+use std::collections::hash_map::Entry;
 use std::collections::HashMap;
 use std::collections::HashSet;
 use std::hash::Hash;
@@ -19,31 +20,32 @@ type Order = usize;
 /// visibly changed.
 ///
 /// [paper]: https://whileydave.com/publications/pk07_jea/
-#[derive(Default, Debug)]
-pub struct DiGraph<V>
+#[derive(Debug)]
+pub struct DiGraph<V, E>
 where
     V: Eq + Hash + Copy,
 {
-    nodes: HashMap<V, Node<V>>,
-    /// Next topological sort order
-    next_ord: Order,
+    nodes: HashMap<V, Node<V, E>>,
+    // Instead of reordering the orders in the graph whenever a node is deleted, we maintain a list
+    // of unused ids that can be handed out later again.
+    unused_order: Vec<Order>,
 }
 
 #[derive(Debug)]
-struct Node<V>
+struct Node<V, E>
 where
     V: Eq + Hash + Clone,
 {
     in_edges: HashSet<V>,
-    out_edges: HashSet<V>,
+    out_edges: HashMap<V, E>,
     // The "Ord" field is a Cell to ensure we can update it in an immutable context.
     // `std::collections::HashMap` doesn't let you have multiple mutable references to elements, but
     // this way we can use immutable references and still update `ord`. This saves quite a few
     // hashmap lookups in the final reorder function.
     ord: Cell<Order>,
 }
 
-impl<V> DiGraph<V>
+impl<V, E> DiGraph<V, E>
 where
     V: Eq + Hash + Copy,
 {
@@ -54,12 +56,18 @@ where
     /// the node in the topological order.
     ///
     /// New nodes are appended to the end of the topological order when added.
-    fn add_node(&mut self, n: V) -> (&mut HashSet<V>, &mut HashSet<V>, Order) {
-        let next_ord = &mut self.next_ord;
+    fn add_node(&mut self, n: V) -> (&mut HashSet<V>, &mut HashMap<V, E>, Order) {
+        // need to compute next id before the call to entry() to avoid duplicate borrow of nodes
+        let fallback_id = self.nodes.len();
 
         let node = self.nodes.entry(n).or_insert_with(|| {
-            let order = *next_ord;
-            *next_ord = next_ord.checked_add(1).expect("Topological order overflow");
+            let order = if let Some(id) = self.unused_order.pop() {
+                // Reuse discarded ordering entry
+                id
+            } else {
+                // Allocate new order id
+                fallback_id
+            };
 
             Node {
                 ord: Cell::new(order),
@@ -77,9 +85,12 @@ where
             Some(Node {
                 out_edges,
                 in_edges,
-                ..
+                ord,
             }) => {
-                out_edges.into_iter().for_each(|m| {
+                // Return ordering to the pool of unused ones
+                self.unused_order.push(ord.get());
+
+                out_edges.into_keys().for_each(|m| {
                     self.nodes.get_mut(&m).unwrap().in_edges.remove(&n);
                 });
 
@@ -96,18 +107,29 @@ where
     ///
     /// Nodes, both from and to, are created as needed when creating new edges. If the new edge
     /// would introduce a cycle, the edge is rejected and `false` is returned.
-    pub(crate) fn add_edge(&mut self, x: V, y: V) -> bool {
+    ///
+    /// # Errors
+    ///
+    /// If the edge would introduce the cycle, the underlying graph is not modified and a list of
+    /// all the edge data in the would-be cycle is returned instead.
+    pub(crate) fn add_edge(&mut self, x: V, y: V, e: impl FnOnce() -> E) -> Result<(), Vec<E>>
+    where
+        E: Clone,
+    {
         if x == y {
             // self-edges are always considered cycles
-            return false;
+            return Err(Vec::new());
         }
 
         let (_, out_edges, ub) = self.add_node(x);
 
-        if !out_edges.insert(y) {
-            // Edge already exists, nothing to be done
-            return true;
-        }
+        match out_edges.entry(y) {
+            Entry::Occupied(_) => {
+                // Edge already exists, nothing to be done
+                return Ok(());
+            }
+            Entry::Vacant(entry) => entry.insert(e()),
+        };
 
         let (in_edges, _, lb) = self.add_node(y);
 
@@ -119,7 +141,7 @@ where
             let mut delta_f = Vec::new();
             let mut delta_b = Vec::new();
 
-            if !self.dfs_f(&self.nodes[&y], ub, &mut visited, &mut delta_f) {
+            if let Err(cycle) = self.dfs_f(&self.nodes[&y], ub, &mut visited, &mut delta_f) {
                 // This edge introduces a cycle, so we want to reject it and remove it from the
                 // graph again to keep the "does not contain cycles" invariant.
 
@@ -129,7 +151,7 @@ where
                 self.nodes.get_mut(&x).map(|node| node.out_edges.remove(&y));
 
                 // No edge was added
-                return false;
+                return Err(cycle);
             }
 
             // No need to check as we should've found the cycle on the forward pass
@@ -141,44 +163,49 @@ where
             self.reorder(delta_f, delta_b);
         }
 
-        true
+        Ok(())
     }
 
     /// Forwards depth-first-search
     fn dfs_f<'a>(
         &'a self,
-        n: &'a Node<V>,
+        n: &'a Node<V, E>,
         ub: Order,
         visited: &mut HashSet<V>,
-        delta_f: &mut Vec<&'a Node<V>>,
-    ) -> bool {
+        delta_f: &mut Vec<&'a Node<V, E>>,
+    ) -> Result<(), Vec<E>>
+    where
+        E: Clone,
+    {
         delta_f.push(n);
 
-        n.out_edges.iter().all(|w| {
+        for (w, e) in &n.out_edges {
             let node = &self.nodes[w];
             let ord = node.ord.get();
 
             if ord == ub {
                 // Found a cycle
-                false
+                return Err(vec![e.clone()]);
             } else if !visited.contains(w) && ord < ub {
                 // Need to check recursively
                 visited.insert(*w);
-                self.dfs_f(node, ub, visited, delta_f)
-            } else {
-                // Already seen this one or not interesting
-                true
+                if let Err(mut chain) = self.dfs_f(node, ub, visited, delta_f) {
+                    chain.push(e.clone());
+                    return Err(chain);
+                }
             }
-        })
+        }
+
+        Ok(())
     }
 
     /// Backwards depth-first-search
     fn dfs_b<'a>(
         &'a self,
-        n: &'a Node<V>,
+        n: &'a Node<V, E>,
         lb: Order,
         visited: &mut HashSet<V>,
-        delta_b: &mut Vec<&'a Node<V>>,
+        delta_b: &mut Vec<&'a Node<V, E>>,
     ) {
         delta_b.push(n);
 
@@ -192,7 +219,7 @@ where
         }
     }
 
-    fn reorder(&self, mut delta_f: Vec<&Node<V>>, mut delta_b: Vec<&Node<V>>) {
+    fn reorder(&self, mut delta_f: Vec<&Node<V, E>>, mut delta_b: Vec<&Node<V, E>>) {
         self.sort(&mut delta_f);
         self.sort(&mut delta_b);
 
@@ -213,50 +240,65 @@ where
         }
     }
 
-    fn sort(&self, ids: &mut [&Node<V>]) {
+    fn sort(&self, ids: &mut [&Node<V, E>]) {
         // Can use unstable sort because mutex ids should not be equal
         ids.sort_unstable_by_key(|v| &v.ord);
     }
 }
 
+// Manual `Default` impl as derive causes unnecessarily strong bounds.
+impl<V, E> Default for DiGraph<V, E>
+where
+    V: Eq + Hash + Copy,
+{
+    fn default() -> Self {
+        Self {
+            nodes: Default::default(),
+            unused_order: Default::default(),
+        }
+    }
+}
+
 #[cfg(test)]
 mod tests {
     use rand::seq::SliceRandom;
     use rand::thread_rng;
 
     use super::*;
 
+    fn nop() {}
+
     #[test]
     fn test_no_self_cycle() {
         // Regression test for /~https://github.com/bertptrs/tracing-mutex/issues/7
         let mut graph = DiGraph::default();
 
-        assert!(!graph.add_edge(1, 1));
+        assert!(graph.add_edge(1, 1, nop).is_err());
     }
 
     #[test]
     fn test_digraph() {
         let mut graph = DiGraph::default();
 
         // Add some safe edges
-        assert!(graph.add_edge(0, 1));
-        assert!(graph.add_edge(1, 2));
-        assert!(graph.add_edge(2, 3));
-        assert!(graph.add_edge(4, 2));
+        assert!(graph.add_edge(0, 1, nop).is_ok());
+        assert!(graph.add_edge(1, 2, nop).is_ok());
+        assert!(graph.add_edge(2, 3, nop).is_ok());
+        assert!(graph.add_edge(4, 2, nop).is_ok());
 
         // Try to add an edge that introduces a cycle
-        assert!(!graph.add_edge(3, 1));
+        assert!(graph.add_edge(3, 1, nop).is_err());
 
         // Add an edge that should reorder 0 to be after 4
-        assert!(graph.add_edge(4, 0));
+        assert!(graph.add_edge(4, 0, nop).is_ok());
     }
 
     /// Fuzz the DiGraph implementation by adding a bunch of valid edges.
     ///
     /// This test generates all possible forward edges in a 100-node graph consisting of natural
     /// numbers, shuffles them, then adds them to the graph. This will always be a valid directed,
     /// acyclic graph because there is a trivial order (the natural numbers) but because the edges
-    /// are added in a random order the DiGraph will still occassionally need to reorder nodes.
+    /// are added in a random order the DiGraph will still occasionally need to reorder nodes.
     #[test]
     fn fuzz_digraph() {
         // Note: this fuzzer is quadratic in the number of nodes, so this cannot be too large or it
@@ -277,7 +319,7 @@ mod tests {
         let mut graph = DiGraph::default();
 
         for (x, y) in edges {
-            assert!(graph.add_edge(x, y));
+            assert!(graph.add_edge(x, y, nop).is_ok());
         }
     }
 }