provide better debugging facilities for nondeterministic tests

This change adds a new tracing facility that helps track down the source of nondeterministic execution. It records, for each branch point, the original (user) source code position leading to this branch, the operation being performed, and the reference that is involved in the branch. If this does not match on a later execution, we dump the mismatched operation, as well as a trace of recent operations, let the current execution run to completion, then panic. A typical trace looks a bit like this: ``` ===== NONDETERMINISTIC EXECUTION DETECTED ===== Previous execution: 13: [tests/nondet.rs:55:28] loom::thread::JoinHandle<()>::join on Thread::2 Current execution: 13: [tests/nondet.rs:55:28] loom::thread::JoinHandle<()>::join on Thread::3 Recent events: 0: [tests/nondet.rs:17:26] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 1: [tests/nondet.rs:18:19] loom::sync::arc::Arc<loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>>::clone on State::1 2: [tests/nondet.rs:35:9] loom::thread::yield_now ...: THREAD SWITCH on Thread::1 3: [tests/nondet.rs:21:30] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 ...: THREAD SWITCH on Thread::0 ...: loom::sync::mutex::MutexGuard<nondet::nondeterministic_execution_detected::State>::drop on Mutex::0 4: [tests/nondet.rs:17:26] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 5: [tests/nondet.rs:18:19] loom::sync::arc::Arc<loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>>::clone on State::1 6: [tests/nondet.rs:35:9] loom::thread::yield_now ...: THREAD SWITCH on Thread::2 7: [tests/nondet.rs:21:30] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 ...: THREAD SWITCH on Thread::0 ...: loom::sync::mutex::MutexGuard<nondet::nondeterministic_execution_detected::State>::drop on Mutex::0 8: [tests/nondet.rs:17:26] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 9: [tests/nondet.rs:18:19] loom::sync::arc::Arc<loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>>::clone on State::1 10: [tests/nondet.rs:35:9] loom::thread::yield_now ...: THREAD SWITCH on Thread::3 11: [tests/nondet.rs:21:30] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 ...: THREAD SWITCH on Thread::0 ...: loom::sync::mutex::MutexGuard<nondet::nondeterministic_execution_detected::State>::drop on Mutex::0 12: [tests/nondet.rs:45:30] loom::sync::mutex::Mutex<nondet::nondeterministic_execution_detected::State>::lock on Mutex::0 ...: loom::sync::mutex::MutexGuard<nondet::nondeterministic_execution_detected::State>::drop on Mutex::0 thread 'nondeterministic_execution_detected' panicked at 'Aborting due to non-deterministic execution', src/rt/execution.rs:262:13 stack backtrace: 0: std::panicking::begin_panic at /local/home/bdonlan/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:497 1: loom::rt::execution::Execution::check_consistency at ./src/rt/execution.rs:262 2: loom::model::Builder::check at ./src/model.rs:208 3: loom::model::model at ./src/model.rs:230 4: nondet::nondeterministic_execution_detected at ./tests/nondet.rs:38 5: nondet::nondeterministic_execution_detected::{{closure}} at ./tests/nondet.rs:9 6: core::ops::function::FnOnce::call_once at /local/home/bdonlan/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227 7: core::ops::function::FnOnce::call_once at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/ops/function.rs:227 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. test nondeterministic_execution_detected ... ok test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out ```
tokio-rs · Oct 23, 2020 · 3484ad0 · 3484ad0
1 parent e3ea36e
commit 3484ad0
Show file tree

Hide file tree

Showing 28 changed files with 870 additions and 136 deletions.
diff --git a/Cargo.toml b/Cargo.toml
@@ -39,3 +39,5 @@ serde = { version = "1.0.92", features = ["derive"], optional = true }
 serde_json = { version = "1.0.33", optional = true }
 
 futures-util = { version = "0.3.0", optional = true }
+
+once_cell = { version = "1.4.1" }
diff --git a/src/future/atomic_waker.rs b/src/future/atomic_waker.rs
@@ -21,16 +21,17 @@ impl AtomicWaker {
     }
 
     /// Registers the current task to be notified on calls to `wake`.
+    #[track_caller]
     pub fn register(&self, waker: Waker) {
-        if dbg!(!self.object.try_acquire_lock()) {
+        if dbg!(!self.object.try_acquire_lock(&trace!())) {
             waker.wake();
             // yield the task and try again... this is a spin lock.
             thread::yield_now();
             return;
         }
 
         *self.waker.lock().unwrap() = Some(waker);
-        dbg!(self.object.release_lock());
+        dbg!(self.object.release_lock(&trace!()));
     }
 
     /// Registers the current task to be woken without consuming the value.
@@ -47,12 +48,13 @@ impl AtomicWaker {
 
     /// Attempts to take the `Waker` value out of the `AtomicWaker` with the
     /// intention that the caller will wake the task later.
+    #[track_caller]
     pub fn take_waker(&self) -> Option<Waker> {
-        dbg!(self.object.acquire_lock());
+        dbg!(self.object.acquire_lock(&trace!()));
 
         let ret = self.waker.lock().unwrap().take();
 
-        dbg!(self.object.release_lock());
+        dbg!(self.object.release_lock(&trace!()));
 
         ret
     }

diff --git a/src/future/mod.rs b/src/future/mod.rs
@@ -13,6 +13,7 @@ use std::mem;
 use std::task::{Context, Poll, RawWaker, RawWakerVTable, Waker};
 
 /// Block the current thread, driving `f` to completion.
+#[track_caller]
 pub fn block_on<F>(f: F) -> F::Output
 where
     F: Future,
@@ -36,7 +37,7 @@ where
             Poll::Pending => {}
         }
 
-        notify.wait();
+        notify.wait(&trace!());
     }
 }
 
@@ -61,15 +62,17 @@ unsafe fn clone_arc_raw(data: *const ()) -> RawWaker {
     RawWaker::new(data, waker_vtable())
 }
 
+#[track_caller]
 unsafe fn wake_arc_raw(data: *const ()) {
     let notify: Arc<rt::Notify> = Arc::from_raw(data as *const _);
-    notify.notify();
+    notify.notify(&trace!());
 }
 
+#[track_caller]
 unsafe fn wake_by_ref_arc_raw(data: *const ()) {
     // Retain Arc, but don't touch refcount by wrapping in ManuallyDrop
     let arc = mem::ManuallyDrop::new(Arc::<rt::Notify>::from_raw(data as *const _));
-    arc.notify();
+    arc.notify(&trace!());
 }
 
 unsafe fn drop_arc_raw(data: *const ()) {

diff --git a/src/lazy_static.rs b/src/lazy_static.rs
@@ -2,7 +2,6 @@
 
 use crate::rt;
 pub use crate::rt::thread::AccessError;
-pub use crate::rt::yield_now;
 use crate::sync::atomic::Ordering;
 
 pub use std::thread::panicking;

diff --git a/src/model.rs b/src/model.rs
@@ -205,6 +205,8 @@ impl Builder {
                 rt::thread_done();
             });
 
+            execution.check_consistency();
+
             execution.check_for_leaks();
 
             if let Some(next) = execution.step() {

diff --git a/src/rt/arc.rs b/src/rt/arc.rs
@@ -3,11 +3,19 @@ use crate::rt::{self, Access, Location, Synchronize, VersionVec};
 
 use std::sync::atomic::Ordering::{Acquire, Release};
 
+use super::{trace::TraceEntity, Trace};
+
 #[derive(Debug)]
 pub(crate) struct Arc {
     state: object::Ref<State>,
 }
 
+impl TraceEntity for Arc {
+    fn as_trace_ref(&self) -> rt::TraceRef {
+        self.state.as_trace_ref().relabel("Arc")
+    }
+}
+
 #[derive(Debug)]
 pub(super) struct State {
     /// Reference count
@@ -59,8 +67,8 @@ impl Arc {
         })
     }
 
-    pub(crate) fn ref_inc(&self) {
-        self.branch(Action::RefInc);
+    pub(crate) fn ref_inc(&self, trace: &Trace) {
+        self.branch(trace, Action::RefInc);
 
         rt::execution(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -69,8 +77,8 @@ impl Arc {
     }
 
     /// Validate a `get_mut` call
-    pub(crate) fn get_mut(&self) -> bool {
-        self.branch(Action::RefDec);
+    pub(crate) fn get_mut(&self, trace: &Trace) -> bool {
+        self.branch(trace, Action::RefDec);
 
         rt::execution(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -89,8 +97,8 @@ impl Arc {
     }
 
     /// Returns true if the memory should be dropped.
-    pub(crate) fn ref_dec(&self) -> bool {
-        self.branch(Action::RefDec);
+    pub(crate) fn ref_dec(&self, trace: &Trace) -> bool {
+        self.branch(trace, Action::RefDec);
 
         rt::execution(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -118,9 +126,9 @@ impl Arc {
         })
     }
 
-    fn branch(&self, action: Action) {
+    fn branch(&self, trace: &Trace, action: Action) {
         let r = self.state;
-        r.branch_action(action);
+        r.branch_action(&trace.with_ref(&self.state), action);
         assert!(
             r.ref_eq(self.state),
             "Internal state mutated during branch. This is \

diff --git a/src/rt/atomic.rs b/src/rt/atomic.rs
@@ -40,12 +40,20 @@ use std::marker::PhantomData;
 use std::sync::atomic::Ordering;
 use std::u16;
 
+use super::{trace::TraceEntity, Trace};
+
 #[derive(Debug)]
 pub(crate) struct Atomic<T> {
     state: object::Ref<State>,
     _p: PhantomData<fn() -> T>,
 }
 
+impl<T> TraceEntity for Atomic<T> {
+    fn as_trace_ref(&self) -> rt::TraceRef {
+        self.state.as_trace_ref().relabel_implicit(self)
+    }
+}
+
 #[derive(Debug)]
 pub(super) struct State {
     /// Where the atomic was created
@@ -175,8 +183,10 @@ impl<T: Numeric> Atomic<T> {
     }
 
     /// Loads a value from the atomic cell.
-    pub(crate) fn load(&self, location: Location, ordering: Ordering) -> T {
-        self.branch(Action::Load);
+    pub(crate) fn load(&self, trace: &Trace, location: Location, ordering: Ordering) -> T {
+        let trace = trace.with_ref(self);
+
+        self.branch(&trace, Action::Load);
 
         super::synchronize(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -187,11 +197,11 @@ impl<T: Numeric> Atomic<T> {
 
                 let n = state.match_load_to_stores(&execution.threads, &mut seed[..], ordering);
 
-                execution.path.push_load(&seed[..n]);
+                execution.path.push_load(&trace, &seed[..n]);
             }
 
             // Get the store to return from this load.
-            let index = execution.path.branch_load();
+            let index = execution.path.branch_load(&trace);
 
             T::from_u64(state.load(&mut execution.threads, index, location, ordering))
         })
@@ -216,8 +226,8 @@ impl<T: Numeric> Atomic<T> {
     }
 
     /// Stores a value into the atomic cell.
-    pub(crate) fn store(&self, location: Location, val: T, ordering: Ordering) {
-        self.branch(Action::Store);
+    pub(crate) fn store(&self, trace: &Trace, location: Location, val: T, ordering: Ordering) {
+        self.branch(&trace.with_ref(self), Action::Store);
 
         super::synchronize(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -240,6 +250,7 @@ impl<T: Numeric> Atomic<T> {
 
     pub(crate) fn rmw<F, E>(
         &self,
+        trace: &Trace,
         location: Location,
         success: Ordering,
         failure: Ordering,
@@ -248,7 +259,9 @@ impl<T: Numeric> Atomic<T> {
     where
         F: FnOnce(T) -> Result<T, E>,
     {
-        self.branch(Action::Rmw);
+        let trace = trace.with_ref(self);
+
+        self.branch(&trace, Action::Rmw);
 
         super::synchronize(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -258,11 +271,11 @@ impl<T: Numeric> Atomic<T> {
                 let mut seed = [0; MAX_ATOMIC_HISTORY];
 
                 let n = state.match_rmw_to_stores(&mut seed[..]);
-                execution.path.push_load(&seed[..n]);
+                execution.path.push_load(&trace, &seed[..n]);
             }
 
             // Get the store to use for the read portion of the rmw operation.
-            let index = execution.path.branch_load();
+            let index = execution.path.branch_load(&trace);
 
             state
                 .rmw(
@@ -324,9 +337,9 @@ impl<T: Numeric> Atomic<T> {
         f(&mut reset.0)
     }
 
-    fn branch(&self, action: Action) {
+    fn branch(&self, trace: &Trace, action: Action) {
         let r = self.state;
-        r.branch_action(action);
+        r.branch_action(trace, action);
         assert!(
             r.ref_eq(self.state),
             "Internal state mutated during branch. This is \

diff --git a/src/rt/condvar.rs b/src/rt/condvar.rs
@@ -3,11 +3,19 @@ use crate::rt::{self, thread, Access, Mutex, VersionVec};
 
 use std::collections::VecDeque;
 
+use super::{trace::TraceEntity, Trace};
+
 #[derive(Debug, Copy, Clone)]
 pub(crate) struct Condvar {
     state: object::Ref<State>,
 }
 
+impl TraceEntity for Condvar {
+    fn as_trace_ref(&self) -> rt::TraceRef {
+        self.state.as_trace_ref().relabel("Condvar")
+    }
+}
+
 #[derive(Debug)]
 pub(super) struct State {
     /// Tracks access to the mutex
@@ -31,8 +39,8 @@ impl Condvar {
     }
 
     /// Blocks the current thread until this condition variable receives a notification.
-    pub(crate) fn wait(&self, mutex: &Mutex) {
-        self.state.branch_opaque();
+    pub(crate) fn wait(&self, trace: &Trace, mutex: &Mutex) {
+        self.state.branch_opaque(&trace.with_ref(self));
 
         rt::execution(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -42,18 +50,18 @@ impl Condvar {
         });
 
         // Release the lock
-        mutex.release_lock();
+        mutex.release_lock(&trace.with_ref(self));
 
         // Disable the current thread
-        rt::park();
+        rt::park(&trace.with_ref(self));
 
         // Acquire the lock again
-        mutex.acquire_lock();
+        mutex.acquire_lock(trace);
     }
 
     /// Wakes up one blocked thread on this condvar.
-    pub(crate) fn notify_one(&self) {
-        self.state.branch_opaque();
+    pub(crate) fn notify_one(&self, trace: &Trace) {
+        self.state.branch_opaque(&trace.with_ref(self));
 
         rt::execution(|execution| {
             let state = self.state.get_mut(&mut execution.objects);
@@ -68,8 +76,8 @@ impl Condvar {
     }
 
     /// Wakes up all blocked threads on this condvar.
-    pub(crate) fn notify_all(&self) {
-        self.state.branch_opaque();
+    pub(crate) fn notify_all(&self, trace: &Trace) {
+        self.state.branch_opaque(&trace.with_ref(self));
 
         rt::execution(|execution| {
             let state = self.state.get_mut(&mut execution.objects);

diff --git a/src/rt/execution.rs b/src/rt/execution.rs
@@ -5,6 +5,8 @@ use std::collections::HashMap;
 use std::convert::TryInto;
 use std::fmt;
 
+use super::Trace;
+
 pub(crate) struct Execution {
     /// Uniquely identifies an execution
     pub(super) id: Id,
@@ -124,7 +126,7 @@ impl Execution {
     }
 
     /// Returns `true` if a switch is required
-    pub(crate) fn schedule(&mut self) -> bool {
+    pub(crate) fn schedule(&mut self, trace: &Trace) -> bool {
         use crate::rt::path::Thread;
 
         // Implementation of the DPOR algorithm.
@@ -177,7 +179,7 @@ impl Execution {
 
         let path_id = self.path.pos();
 
-        let next = self.path.branch_thread(self.id, {
+        let next = self.path.branch_thread(trace, self.id, {
             self.threads.iter().map(|(i, th)| {
                 if initial.is_none() && th.is_runnable() {
                     initial = Some(i);
@@ -197,6 +199,14 @@ impl Execution {
 
         let switched = Some(self.threads.active_id()) != next;
 
+        if switched {
+            if let Some(thread_id) = next {
+                self.path.record_event(
+                    &Trace::opaque("THREAD SWITCH").with_custom_ref("Thread", thread_id.as_usize()),
+                )
+            }
+        }
+
         self.threads.set_active(next);
 
         // There is no active thread. Unless all threads have terminated, the
@@ -246,6 +256,13 @@ impl Execution {
         curr_thread != self.threads.active_id()
     }
 
+    /// Panics if execution was determined to be non-deterministic
+    pub(crate) fn check_consistency(&self) {
+        if self.path.is_inconsistent() {
+            panic!("Aborting due to non-deterministic execution");
+        }
+    }
+
     /// Panics if any leaks were detected
     pub(crate) fn check_for_leaks(&self) {
         self.objects.check_for_leaks();
Original file line number	Diff line number	Diff line change
Expand Up		@@ -39,3 +39,5 @@ serde = { version = "1.0.92", features = ["derive"], optional = true }
		serde_json = { version = "1.0.33", optional = true }

		futures-util = { version = "0.3.0", optional = true }

		once_cell = { version = "1.4.1" }