Commit d8c559f
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 <[email protected]>File tree
7 files changed
+198
-59
lines changed- examples
- src
7 files changed
+198
-59
lines changed| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
11 | 11 | | |
12 | 12 | | |
13 | 13 | | |
| 14 | + | |
14 | 15 | | |
15 | 16 | | |
16 | 17 | | |
| |||
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
31 | 31 | | |
32 | 32 | | |
33 | 33 | | |
| 34 | + | |
| 35 | + | |
34 | 36 | | |
35 | 37 | | |
36 | 38 | | |
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
| 1 | + | |
| 2 | + | |
| 3 | + | |
| 4 | + | |
| 5 | + | |
| 6 | + | |
| 7 | + | |
| 8 | + | |
| 9 | + | |
| 10 | + | |
| 11 | + | |
| 12 | + | |
| 13 | + | |
| 14 | + | |
| 15 | + | |
| 16 | + | |
| 17 | + | |
| 18 | + | |
| 19 | + | |
| 20 | + | |
| 21 | + | |
| 22 | + | |
| 23 | + | |
| 24 | + | |
| 25 | + | |
| 26 | + | |
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
1 | 1 | | |
| 2 | + | |
2 | 3 | | |
3 | 4 | | |
4 | 5 | | |
| |||
19 | 20 | | |
20 | 21 | | |
21 | 22 | | |
22 | | - | |
23 | | - | |
| 23 | + | |
| 24 | + | |
24 | 25 | | |
25 | 26 | | |
26 | 27 | | |
27 | | - | |
28 | | - | |
29 | | - | |
| 28 | + | |
| 29 | + | |
| 30 | + | |
| 31 | + | |
30 | 32 | | |
31 | 33 | | |
32 | 34 | | |
33 | | - | |
| 35 | + | |
34 | 36 | | |
35 | 37 | | |
36 | 38 | | |
37 | 39 | | |
38 | | - | |
| 40 | + | |
39 | 41 | | |
40 | 42 | | |
41 | 43 | | |
42 | 44 | | |
43 | 45 | | |
44 | 46 | | |
45 | 47 | | |
46 | | - | |
| 48 | + | |
47 | 49 | | |
48 | 50 | | |
49 | 51 | | |
| |||
54 | 56 | | |
55 | 57 | | |
56 | 58 | | |
57 | | - | |
58 | | - | |
| 59 | + | |
| 60 | + | |
| 61 | + | |
59 | 62 | | |
60 | 63 | | |
61 | | - | |
62 | | - | |
| 64 | + | |
| 65 | + | |
| 66 | + | |
| 67 | + | |
| 68 | + | |
| 69 | + | |
| 70 | + | |
63 | 71 | | |
64 | 72 | | |
65 | 73 | | |
| |||
77 | 85 | | |
78 | 86 | | |
79 | 87 | | |
80 | | - | |
| 88 | + | |
81 | 89 | | |
82 | | - | |
| 90 | + | |
| 91 | + | |
| 92 | + | |
| 93 | + | |
83 | 94 | | |
84 | 95 | | |
85 | 96 | | |
| |||
96 | 107 | | |
97 | 108 | | |
98 | 109 | | |
99 | | - | |
| 110 | + | |
| 111 | + | |
| 112 | + | |
| 113 | + | |
| 114 | + | |
| 115 | + | |
| 116 | + | |
| 117 | + | |
| 118 | + | |
100 | 119 | | |
101 | 120 | | |
102 | | - | |
| 121 | + | |
103 | 122 | | |
104 | 123 | | |
105 | 124 | | |
106 | 125 | | |
107 | | - | |
108 | | - | |
109 | | - | |
110 | | - | |
| 126 | + | |
| 127 | + | |
| 128 | + | |
| 129 | + | |
| 130 | + | |
| 131 | + | |
| 132 | + | |
111 | 133 | | |
112 | 134 | | |
113 | 135 | | |
| |||
119 | 141 | | |
120 | 142 | | |
121 | 143 | | |
122 | | - | |
| 144 | + | |
123 | 145 | | |
124 | 146 | | |
125 | 147 | | |
| |||
129 | 151 | | |
130 | 152 | | |
131 | 153 | | |
132 | | - | |
| 154 | + | |
133 | 155 | | |
134 | 156 | | |
135 | 157 | | |
| |||
141 | 163 | | |
142 | 164 | | |
143 | 165 | | |
144 | | - | |
| 166 | + | |
145 | 167 | | |
146 | 168 | | |
147 | 169 | | |
148 | 170 | | |
149 | 171 | | |
150 | | - | |
| 172 | + | |
151 | 173 | | |
152 | 174 | | |
153 | | - | |
154 | | - | |
| 175 | + | |
| 176 | + | |
| 177 | + | |
| 178 | + | |
| 179 | + | |
155 | 180 | | |
156 | 181 | | |
157 | | - | |
| 182 | + | |
158 | 183 | | |
159 | 184 | | |
160 | 185 | | |
161 | 186 | | |
162 | 187 | | |
163 | | - | |
| 188 | + | |
164 | 189 | | |
165 | 190 | | |
166 | 191 | | |
167 | | - | |
168 | | - | |
169 | | - | |
170 | | - | |
| 192 | + | |
| 193 | + | |
| 194 | + | |
| 195 | + | |
171 | 196 | | |
172 | | - | |
| 197 | + | |
| 198 | + | |
| 199 | + | |
173 | 200 | | |
174 | 201 | | |
175 | 202 | | |
176 | 203 | | |
177 | 204 | | |
178 | | - | |
| 205 | + | |
179 | 206 | | |
180 | 207 | | |
181 | | - | |
| 208 | + | |
182 | 209 | | |
183 | 210 | | |
184 | 211 | | |
| |||
192 | 219 | | |
193 | 220 | | |
194 | 221 | | |
195 | | - | |
| 222 | + | |
196 | 223 | | |
197 | 224 | | |
198 | 225 | | |
| |||
213 | 240 | | |
214 | 241 | | |
215 | 242 | | |
216 | | - | |
| 243 | + | |
217 | 244 | | |
218 | 245 | | |
219 | 246 | | |
220 | 247 | | |
221 | 248 | | |
| 249 | + | |
| 250 | + | |
| 251 | + | |
| 252 | + | |
| 253 | + | |
| 254 | + | |
| 255 | + | |
| 256 | + | |
| 257 | + | |
| 258 | + | |
| 259 | + | |
| 260 | + | |
| 261 | + | |
222 | 262 | | |
223 | 263 | | |
224 | 264 | | |
225 | 265 | | |
226 | 266 | | |
227 | 267 | | |
228 | 268 | | |
| 269 | + | |
| 270 | + | |
229 | 271 | | |
230 | 272 | | |
231 | 273 | | |
232 | 274 | | |
233 | 275 | | |
234 | | - | |
| 276 | + | |
235 | 277 | | |
236 | 278 | | |
237 | 279 | | |
238 | 280 | | |
239 | 281 | | |
240 | 282 | | |
241 | 283 | | |
242 | | - | |
243 | | - | |
244 | | - | |
245 | | - | |
| 284 | + | |
| 285 | + | |
| 286 | + | |
| 287 | + | |
246 | 288 | | |
247 | 289 | | |
248 | | - | |
| 290 | + | |
249 | 291 | | |
250 | 292 | | |
251 | | - | |
| 293 | + | |
252 | 294 | | |
253 | 295 | | |
254 | 296 | | |
255 | 297 | | |
256 | 298 | | |
257 | 299 | | |
258 | 300 | | |
259 | | - | |
| 301 | + | |
260 | 302 | | |
261 | 303 | | |
262 | 304 | | |
| |||
277 | 319 | | |
278 | 320 | | |
279 | 321 | | |
280 | | - | |
| 322 | + | |
281 | 323 | | |
282 | 324 | | |
283 | 325 | | |
0 commit comments