diff --git a/Cargo.lock b/Cargo.lock index 1eeeff1..15a8b8a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -72,19 +72,6 @@ dependencies = [ "wasm-bindgen", ] -[[package]] -name = "dashmap" -version = "5.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "907076dfda823b0b36d2a1bb5f90c96660a5bbcd7729e10727f07858f22c4edc" -dependencies = [ - "cfg-if", - "hashbrown", - "lock_api", - "once_cell", - "parking_lot_core", -] - [[package]] name = "document-features" version = "0.2.7" @@ -210,12 +197,6 @@ dependencies = [ "slab", ] -[[package]] -name = "hashbrown" -version = "0.12.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8a9ee70c43aaf417c914396645a0fa852624801b24ebb7ae78fe8272889ac888" - [[package]] name = "hermit-abi" version = "0.3.3" @@ -429,6 +410,12 @@ dependencies = [ "windows-sys 0.52.0", ] +[[package]] +name = "scc" +version = "2.0.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f6ffca2d370bbde3a120a882da4094bdb29b4fcb5ffbdc482c9fdf2903c16e50" + [[package]] name = "scoped-tls" version = "1.0.0" @@ -445,14 +432,15 @@ checksum = "d29ab0c6d3fc0ee92fe66e2d99f700eab17a8d57d1c1d3b748380fb20baa78cd" name = "serial_test" version = "3.0.0" dependencies = [ - "dashmap", "document-features", + "env_logger", "fslock", "futures", "itertools", "log", "once_cell", "parking_lot", + "scc", "serial_test_derive", "tokio", ] @@ -476,6 +464,7 @@ dependencies = [ "env_logger", "futures-util", "lock_api", + "log", "once_cell", "parking_lot", "scoped-tls", diff --git a/serial_test/Cargo.toml b/serial_test/Cargo.toml index a0bcc67..fdcbd91 100644 --- a/serial_test/Cargo.toml +++ b/serial_test/Cargo.toml @@ -20,7 +20,8 @@ log = { version = "0.4", optional = true } futures = { version = "^0.3", default_features = false, features = [ "executor", ], optional = true} -dashmap = { version = "5"} +scc = { version = "2"} +env_logger = {version="0.10", optional=true} [dev-dependencies] itertools = "0.10" @@ -32,6 +33,9 @@ default = ["logging", "async"] ## Switches on debug logging (and requires the `log` package) logging = ["log"] +## Switches on debug with env_logger. Generally only needed by internal serial_test work. +test_logging = ["logging", "env_logger", "serial_test_derive/test_logging"] + ## Enables async features (and requires the `futures` package) async = ["futures", "serial_test_derive/async"] @@ -48,4 +52,4 @@ rustdoc-args = ["--cfg", "docsrs"] [package.metadata.cargo-all-features] skip_optional_dependencies = true -denylist = ["docsrs"] \ No newline at end of file +denylist = ["docsrs", "test_logging"] \ No newline at end of file diff --git a/serial_test/src/code_lock.rs b/serial_test/src/code_lock.rs index ba365c6..cbb2161 100644 --- a/serial_test/src/code_lock.rs +++ b/serial_test/src/code_lock.rs @@ -1,11 +1,7 @@ use crate::rwlock::{Locks, MutexGuardWrapper}; -use dashmap::{try_result::TryResult, DashMap}; -#[cfg(feature = "logging")] -use log::debug; use once_cell::sync::OnceCell; +use scc::{hash_map::Entry, HashMap}; use std::sync::atomic::AtomicU32; -#[cfg(feature = "logging")] -use std::time::Instant; #[derive(Clone)] pub(crate) struct UniqueReentrantMutex { @@ -41,51 +37,34 @@ impl UniqueReentrantMutex { } #[inline] -pub(crate) fn global_locks() -> &'static DashMap { - static LOCKS: OnceCell> = OnceCell::new(); - LOCKS.get_or_init(DashMap::new) +pub(crate) fn global_locks() -> &'static HashMap { + #[cfg(feature = "test_logging")] + let _ = env_logger::builder().try_init(); + static LOCKS: OnceCell> = OnceCell::new(); + LOCKS.get_or_init(HashMap::new) } static MUTEX_ID: AtomicU32 = AtomicU32::new(1); -impl Default for UniqueReentrantMutex { - fn default() -> Self { +impl UniqueReentrantMutex { + fn new_mutex(name: &str) -> Self { Self { - locks: Locks::new(), + locks: Locks::new(name), id: MUTEX_ID.fetch_add(1, std::sync::atomic::Ordering::SeqCst), } } } pub(crate) fn check_new_key(name: &str) { - #[cfg(feature = "logging")] - let start = Instant::now(); - loop { - #[cfg(feature = "logging")] - { - let duration = start.elapsed(); - debug!("Waiting for '{}' {:?}", name, duration); - } - // Check if a new key is needed. Just need a read lock, which can be done in sync with everyone else - match global_locks().try_get(name) { - TryResult::Present(_) => { - return; - } - TryResult::Locked => { - continue; // wasn't able to get read lock - } - TryResult::Absent => {} // do the write path below - }; - - // This is the rare path, which avoids the multi-writer situation mostly - let try_entry = global_locks().try_entry(name.to_string()); + // Check if a new key is needed. Just need a read lock, which can be done in sync with everyone else + if global_locks().contains(name) { + return; + }; - if let Some(entry) = try_entry { - entry.or_default(); - return; - } - - // If the try_entry fails, then go around the loop again - // Odds are another test was also locking on the write and has now written the key - } + // This is the rare path, which avoids the multi-writer situation mostly + let entry = global_locks().entry(name.to_owned()); + match entry { + Entry::Occupied(o) => o, + Entry::Vacant(v) => v.insert_entry(UniqueReentrantMutex::new_mutex(name)), + }; } diff --git a/serial_test/src/parallel_code_lock.rs b/serial_test/src/parallel_code_lock.rs index 0d215ce..a474365 100644 --- a/serial_test/src/parallel_code_lock.rs +++ b/serial_test/src/parallel_code_lock.rs @@ -7,12 +7,12 @@ use std::panic; fn get_locks( names: Vec<&str>, -) -> Vec> { +) -> Vec { names .into_iter() .map(|name| { check_new_key(name); - global_locks().get(name).expect("key to be set") + global_locks().get(name).expect("key to be set").get().clone() }) .collect::>() } @@ -103,6 +103,7 @@ mod tests { global_locks() .get("unlock_on_assert_sync_without_return") .unwrap() + .get() .parallel_count(), 0 ); @@ -124,6 +125,7 @@ mod tests { global_locks() .get("unlock_on_assert_sync_with_return") .unwrap() + .get() .parallel_count(), 0 ); @@ -153,6 +155,7 @@ mod tests { global_locks() .get("unlock_on_assert_async_without_return") .unwrap() + .get() .parallel_count(), 0 ); @@ -186,6 +189,7 @@ mod tests { global_locks() .get("unlock_on_assert_async_with_return") .unwrap() + .get() .parallel_count(), 0 ); diff --git a/serial_test/src/rwlock.rs b/serial_test/src/rwlock.rs index c61944b..f2e5376 100644 --- a/serial_test/src/rwlock.rs +++ b/serial_test/src/rwlock.rs @@ -1,5 +1,7 @@ use parking_lot::{Condvar, Mutex, ReentrantMutex, ReentrantMutexGuard}; use std::{sync::Arc, time::Duration}; +#[cfg(feature = "logging")] +use log::debug; struct LockState { parallels: u32, @@ -14,6 +16,9 @@ struct LockData { #[derive(Clone)] pub(crate) struct Locks { arc: Arc, + // Name we're locking for (mostly test usage) + #[cfg(feature = "logging")] + pub(crate) name: String } pub(crate) struct MutexGuardWrapper<'a> { @@ -24,18 +29,22 @@ pub(crate) struct MutexGuardWrapper<'a> { impl<'a> Drop for MutexGuardWrapper<'a> { fn drop(&mut self) { + #[cfg(feature = "logging")] + debug!("End serial"); self.locks.arc.condvar.notify_one(); } } impl Locks { - pub fn new() -> Locks { + pub fn new(name: &str) -> Locks { Locks { arc: Arc::new(LockData { mutex: Mutex::new(LockState { parallels: 0 }), condvar: Condvar::new(), serial: Default::default(), }), + #[cfg(feature = "logging")] + name: name.to_owned() } } @@ -45,16 +54,25 @@ impl Locks { } pub fn serial(&self) -> MutexGuardWrapper { + #[cfg(feature = "logging")] + debug!("Get serial lock '{}'", self.name); let mut lock_state = self.arc.mutex.lock(); loop { + #[cfg(feature = "logging")] + debug!("Serial acquire {} {}", lock_state.parallels, self.name); // If all the things we want are true, try to lock out serial if lock_state.parallels == 0 { let possible_serial_lock = self.arc.serial.try_lock(); if let Some(serial_lock) = possible_serial_lock { + #[cfg(feature = "logging")] + debug!("Got serial '{}'", self.name); return MutexGuardWrapper { mutex_guard: serial_lock, locks: self.clone(), }; + } else { + #[cfg(feature = "logging")] + debug!("Someone else has serial '{}'", self.name); } } @@ -65,8 +83,12 @@ impl Locks { } pub fn start_parallel(&self) { + #[cfg(feature = "logging")] + debug!("Get parallel lock '{}'", self.name); let mut lock_state = self.arc.mutex.lock(); loop { + #[cfg(feature = "logging")] + debug!("Parallel, existing {} '{}'", lock_state.parallels, self.name); if lock_state.parallels > 0 { // fast path, as someone else already has it locked lock_state.parallels += 1; @@ -75,11 +97,15 @@ impl Locks { let possible_serial_lock = self.arc.serial.try_lock(); if possible_serial_lock.is_some() { + #[cfg(feature = "logging")] + debug!("Parallel first '{}'", self.name); // We now know no-one else has the serial lock, so we can add to parallel lock_state.parallels = 1; // Had to have been 0 before, as otherwise we'd have hit the fast path return; } + #[cfg(feature = "logging")] + debug!("Parallel waiting '{}'", self.name); self.arc .condvar .wait_for(&mut lock_state, Duration::from_secs(1)); @@ -87,6 +113,8 @@ impl Locks { } pub fn end_parallel(&self) { + #[cfg(feature = "logging")] + debug!("End parallel"); let mut lock_state = self.arc.mutex.lock(); assert!(lock_state.parallels > 0); lock_state.parallels -= 1; diff --git a/serial_test/src/serial_code_lock.rs b/serial_test/src/serial_code_lock.rs index f72108e..2a270b9 100644 --- a/serial_test/src/serial_code_lock.rs +++ b/serial_test/src/serial_code_lock.rs @@ -9,7 +9,7 @@ macro_rules! core_internal { .into_iter() .map(|name| { check_new_key(name); - global_locks().get(name).expect("key to be set") + global_locks().get(name).expect("key to be set").get().clone() }) .collect(); let _guards: Vec<_> = unlocks.iter().map(|unlock| unlock.lock()).collect(); @@ -84,7 +84,7 @@ mod tests { check_new_key("foo"); { let unlock = local_locks.get("foo").expect("read didn't work"); - let mutex = unlock.value(); + let mutex = unlock.get(); let mut ptr_guard = local_ptrs .try_write_for(Duration::from_secs(1)) @@ -113,6 +113,6 @@ mod tests { assert!(false); }) }); - assert!(!global_locks().get("assert").unwrap().is_locked()); + assert!(!global_locks().get("assert").unwrap().get().is_locked()); } } diff --git a/serial_test_derive/Cargo.toml b/serial_test_derive/Cargo.toml index db150fe..2d3e135 100644 --- a/serial_test_derive/Cargo.toml +++ b/serial_test_derive/Cargo.toml @@ -22,4 +22,6 @@ env_logger = "0.10" prettyplease = "0.2" [features] -async = [] \ No newline at end of file +default = [] +async = [] +test_logging = [] \ No newline at end of file diff --git a/serial_test_derive/src/lib.rs b/serial_test_derive/src/lib.rs index cbf1323..d9465ea 100644 --- a/serial_test_derive/src/lib.rs +++ b/serial_test_derive/src/lib.rs @@ -382,6 +382,15 @@ fn fn_setup( } let vis = ast.vis; let name = ast.sig.ident; + #[cfg(all(feature = "test_logging", not(test)))] + let print_name = { + let print_str = format!("Starting {name}"); + quote! { + println!(#print_str); + } + }; + #[cfg(any(not(feature = "test_logging"), test))] + let print_name = quote! {}; let return_type = match ast.sig.output { syn::ReturnType::Default => None, syn::ReturnType::Type(_rarrow, ref box_type) => Some(box_type.deref()), @@ -402,6 +411,7 @@ fn fn_setup( #(#attrs) * #vis async fn #name () -> #ret { + #print_name serial_test::#fnname(vec![#(#names ),*], #path, #temp_fn()).await } } @@ -412,6 +422,7 @@ fn fn_setup( #(#attrs) * #vis fn #name () -> #ret { + #print_name serial_test::#fnname(vec![#(#names ),*], #path, || #block ) } } @@ -429,6 +440,7 @@ fn fn_setup( #(#attrs) * #vis async fn #name () { + #print_name serial_test::#fnname(vec![#(#names ),*], #path, #temp_fn()).await; } } @@ -439,6 +451,7 @@ fn fn_setup( #(#attrs) * #vis fn #name () { + #print_name serial_test::#fnname(vec![#(#names ),*], #path, || #block ); } } @@ -470,6 +483,10 @@ mod tests { use quote::quote; use std::iter::FromIterator; + fn init() { + let _ = env_logger::builder().is_test(false).try_init(); + } + fn unparse(input: TokenStream) -> String { let item = syn::parse2(input).unwrap(); let file = syn::File { @@ -488,6 +505,7 @@ mod tests { #[test] fn test_serial() { + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { #[test] @@ -505,6 +523,7 @@ mod tests { #[test] fn test_serial_with_pub() { + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { #[test] @@ -522,7 +541,7 @@ mod tests { #[test] fn test_other_attributes() { - let _ = env_logger::builder().is_test(true).try_init(); + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { #[test] @@ -547,6 +566,7 @@ mod tests { #[test] #[cfg(feature = "async")] fn test_serial_async() { + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { async fn foo() {} @@ -564,6 +584,7 @@ mod tests { #[test] #[cfg(feature = "async")] fn test_serial_async_return() { + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { async fn foo() -> Result<(), ()> { Ok(()) } @@ -580,6 +601,7 @@ mod tests { #[test] fn test_file_serial() { + init(); let attrs: Vec<_> = quote! { foo }.into_iter().collect(); let input = quote! { #[test] @@ -600,6 +622,7 @@ mod tests { #[test] fn test_file_serial_no_args() { + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { #[test] @@ -620,6 +643,7 @@ mod tests { #[test] fn test_file_serial_with_path() { + init(); let attrs: Vec<_> = quote! { foo, path => "bar_path" }.into_iter().collect(); let input = quote! { #[test] @@ -640,6 +664,7 @@ mod tests { #[test] fn test_single_attr() { + init(); let attrs: Vec<_> = quote! { one}.into_iter().collect(); let input = quote! { #[test] @@ -660,6 +685,7 @@ mod tests { #[test] fn test_multiple_attr() { + init(); let attrs: Vec<_> = quote! { two, one }.into_iter().collect(); let input = quote! { #[test] @@ -680,6 +706,7 @@ mod tests { #[test] fn test_mod() { + init(); let attrs = proc_macro2::TokenStream::new(); let input = quote! { #[cfg(test)] diff --git a/serial_test_test/Cargo.toml b/serial_test_test/Cargo.toml index 5d0f234..8a12f55 100644 --- a/serial_test_test/Cargo.toml +++ b/serial_test_test/Cargo.toml @@ -15,6 +15,7 @@ parking_lot = "^0.12" lock_api = "^0.4.7" wasm-bindgen-test = {version="0.3.20", optional=true} scoped-tls = {version="1", optional=true} +log = { version = "0.4" } [dev-dependencies] tokio = { version = "^1.27", features = ["macros", "rt"] } @@ -22,7 +23,7 @@ actix-rt = { version = "^2.8", features = ["macros"] } futures-util = {version = "^0.3", default_features = false } [features] -default = ["serial_test/logging", "async"] +default = ["serial_test/logging", "async", "serial_test/test_logging"] file_locks = ["serial_test/file_locks"] async = ["serial_test/async", "wasm-bindgen-test", "scoped-tls"] diff --git a/serial_test_test/src/lib.rs b/serial_test_test/src/lib.rs index 135a513..5856890 100644 --- a/serial_test_test/src/lib.rs +++ b/serial_test_test/src/lib.rs @@ -1,5 +1,3 @@ -#![allow(clippy::print_stdout)] // because test code - //! Not inside the cfg(test) block because of //! ``` //! #[macro_use] extern crate serial_test; @@ -47,30 +45,31 @@ use std::{ thread, time::Duration, }; +use log::info; static LOCK: AtomicUsize = AtomicUsize::new(0); fn init() { - let _ = env_logger::builder().is_test(false).try_init(); + let _ = env_logger::builder().try_init(); } pub fn test_fn(count: usize) { init(); - println!("(non-fs) Start {}", count); + info!("(non-fs) Start {}", count); LOCK.store(count, Ordering::Relaxed); thread::sleep(Duration::from_millis(1000 * (count as u64))); - println!("(non-fs) End {}", count); + info!("(non-fs) End {}", count); assert_eq!(LOCK.load(Ordering::Relaxed), count); } pub fn fs_test_fn(count: usize) { init(); - println!("(fs) Start {}", count); + info!("(fs) Start {}", count); let mut pathbuf = env::temp_dir(); pathbuf.push("serial-test-test"); fs::write(pathbuf.as_path(), count.to_ne_bytes()).unwrap(); thread::sleep(Duration::from_millis(1000 * (count as u64))); - println!("(fs) End {}", count); + info!("(fs) End {}", count); let loaded = fs::read(pathbuf.as_path()) .map(|bytes| usize::from_ne_bytes(bytes.as_slice().try_into().unwrap())) @@ -89,6 +88,7 @@ mod parallel_attr_tests {} #[cfg(test)] mod tests { use super::{init, test_fn}; + use log::info; use once_cell::sync::OnceCell; use parking_lot::Mutex; use serial_test::{parallel, serial}; @@ -264,9 +264,9 @@ mod tests { #[parallel(ordering_key)] fn parallel_with_key_1() { thread::sleep(Duration::from_secs(1)); - println!("Waiting barrier 1"); + info!("Waiting barrier 1"); parallel_barrier().wait(); - println!("Waiting lock 1"); + info!("Waiting lock 1"); THREAD_ORDERINGS.lock().push(false); } @@ -274,9 +274,9 @@ mod tests { #[parallel(ordering_key)] fn parallel_with_key_2() { thread::sleep(Duration::from_secs(2)); - println!("Waiting barrier 2"); + info!("Waiting barrier 2"); parallel_barrier().wait(); - println!("Waiting lock 2"); + info!("Waiting lock 2"); THREAD_ORDERINGS.lock().push(false); } @@ -284,9 +284,9 @@ mod tests { #[parallel(ordering_key)] fn parallel_with_key_3() { thread::sleep(Duration::from_secs(3)); - println!("Waiting barrier 3"); + info!("Waiting barrier 3"); parallel_barrier().wait(); - println!("Waiting lock 3"); + info!("Waiting lock 3"); THREAD_ORDERINGS.lock().push(false); } @@ -322,9 +322,9 @@ mod tests { fn file_parallel_with_key_1() { init(); thread::sleep(Duration::from_secs(1)); - println!("Waiting barrier 1"); + info!("Waiting barrier 1"); fs_parallel_barrier().wait(); - println!("Waiting lock 1"); + info!("Waiting lock 1"); FS_THREAD_ORDERINGS.lock().push(false); } @@ -334,9 +334,9 @@ mod tests { fn file_parallel_with_key_2() { init(); thread::sleep(Duration::from_secs(1)); - println!("Waiting barrier 2"); + info!("Waiting barrier 2"); fs_parallel_barrier().wait(); - println!("Waiting lock 2"); + info!("Waiting lock 2"); FS_THREAD_ORDERINGS.lock().push(false); } @@ -346,9 +346,9 @@ mod tests { fn file_parallel_with_key_3() { init(); thread::sleep(Duration::from_secs(1)); - println!("Waiting barrier 3"); + info!("Waiting barrier 3"); fs_parallel_barrier().wait(); - println!("Waiting lock 3"); + info!("Waiting lock 3"); FS_THREAD_ORDERINGS.lock().push(false); }