nnethercote / dhat-rs

Heap profiling and ad hoc profiling for Rust programs.
Apache License 2.0
744 stars 36 forks source link

parking_lot's Mutex allocates, causing deadlock #25

Closed cstrahan-blueshift closed 2 years ago

cstrahan-blueshift commented 2 years ago

When creating a moka::sync::Cache or moka::future::Cache the process hangs, unless I remove/comment out the let _profiler = dhat::Profiler::new_heap(); line.

I have a minimal, self contained reproducer here: https://github.com/cstrahan-blueshift/dhat_moka_hang_repro

cstrahan-blueshift commented 2 years ago

I tried removing the let _profiler = dhat::Profiler::new_heap(); line, and but leaving the #[global_allocator] lines in place:

use moka::sync::Cache;

#[global_allocator]
static ALLOC: dhat::Alloc = dhat::Alloc;

fn main() {
    let _cache: Cache<String, String> = Cache::builder().max_capacity(1).build();
}

This is enough to cause the program to hang maybe 1 out of 10 runs (there's some apparent nondeterminism).

Looking at the stack in gdb in this scenario:

(gdb) info stack
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x000055fe6771c5d1 in parking_lot_core::thread_parker::imp::ThreadParker::futex_wait () at src/thread_parker/linux.rs:112
#2  parking_lot_core::thread_parker::imp::{impl#0}::park () at src/thread_parker/linux.rs:66
#3  parking_lot_core::word_lock::{impl#1}::lock_slow::{closure#0} () at src/word_lock.rs:167
#4  parking_lot_core::word_lock::with_thread_data<usize, parking_lot_core::word_lock::{impl#1}::lock_slow::{closure_env#0}> () at src/word_lock.rs:67
#5  parking_lot_core::word_lock::WordLock::lock_slow () at src/word_lock.rs:136
#6  0x000055fe6774e7bc in parking_lot_core::word_lock::WordLock::lock () at src/word_lock.rs:97
#7  parking_lot_core::parking_lot::grow_hashtable () at src/parking_lot.rs:276
#8  parking_lot_core::parking_lot::ThreadData::new () at src/parking_lot.rs:180
#9  0x000055fe6774d800 in parking_lot_core::parking_lot::with_thread_data::THREAD_DATA::__init () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/parking_lot_core-0.9.4/src/parking_lot.rs:202
#10 parking_lot_core::parking_lot::with_thread_data::THREAD_DATA::__getit::{closure#0} () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:353
#11 std::thread::local::lazy::LazyKeyInner::initialize<parking_lot_core::parking_lot::ThreadData, parking_lot_core::parking_lot::with_thread_data::THREAD_DATA::__getit::{closure_env#0}> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:809
#12 std::thread::local::fast::Key::try_initialize<parking_lot_core::parking_lot::ThreadData, parking_lot_core::parking_lot::with_thread_data::THREAD_DATA::__getit::{closure_env#0}> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:987
#13 0x000055fe6771bce6 in std::thread::local::fast::Key::get<parking_lot_core::parking_lot::ThreadData, parking_lot_core::parking_lot::with_thread_data::THREAD_DATA::__getit::{closure_env#0}> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:970
#14 parking_lot_core::parking_lot::with_thread_data::THREAD_DATA::__getit () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:345
#15 std::thread::local::LocalKey::try_with<parking_lot_core::parking_lot::ThreadData, parking_lot_core::parking_lot::with_thread_data::{closure_env#0}<parking_lot_core::parking_lot::ParkResult, parking_lot_core::parking_lot::park::{closure_env#0}<parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#0}, parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#1}, parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#2}>>, *const parking_lot_core::parking_lot::ThreadData> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:444
#16 parking_lot_core::parking_lot::with_thread_data<parking_lot_core::parking_lot::ParkResult, parking_lot_core::parking_lot::park::{closure_env#0}<parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#0}, parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#1}, parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#2}>> ()
    at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/parking_lot_core-0.9.4/src/parking_lot.rs:203
#17 parking_lot_core::parking_lot::park<parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#0}, parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#1}, parking_lot::raw_mutex::{impl#3}::lock_slow::{closure_env#2}> ()
    at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/parking_lot_core-0.9.4/src/parking_lot.rs:600
#18 parking_lot::raw_mutex::RawMutex::lock_slow () at src/raw_mutex.rs:262
#19 0x000055fe6773ed07 in parking_lot::raw_mutex::{impl#0}::lock () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/parking_lot-0.12.1/src/raw_mutex.rs:72
#20 lock_api::mutex::Mutex::lock<parking_lot::raw_mutex::RawMutex, dhat::Phase<dhat::Globals>> () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/lock_api-0.4.9/src/mutex.rs:214
#21 dhat::{impl#7}::alloc () at src/lib.rs:1221
#22 0x000055fe6774a7b7 in alloc::raw_vec::finish_grow<alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/result.rs:2134
#23 0x000055fe6771a152 in alloc::raw_vec::RawVec::grow_amortized<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/raw_vec.rs:400
#24 alloc::raw_vec::{impl#1}::reserve::do_reserve_and_handle<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/raw_vec.rs:285
#25 0x000055fe67748fe8 in alloc::raw_vec::RawVec::reserve<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/raw_vec.rs:289
#26 alloc::vec::Vec::reserve<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/vec/mod.rs:841
#27 alloc::vec::Vec::append_elements<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/vec/mod.rs:1834
#28 alloc::vec::spec_extend::{impl#4}::spec_extend<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/vec/spec_extend.rs:85
#29 alloc::vec::Vec::extend_from_slice<u8, alloc::alloc::Global> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/vec/mod.rs:2283
#30 alloc::string::String::push_str () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/string.rs:925
#31 alloc::string::{impl#63}::write_str () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/string.rs:2818
#32 0x000055fe67784d70 in core::fmt::num::imp::fmt_u64 () at library/core/src/fmt/num.rs:273
#33 core::fmt::num::imp::{impl#7}::fmt () at library/core/src/fmt/num.rs:287
#34 0x000055fe677493ab in alloc::string::{impl#40}::to_string<usize> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/alloc/src/string.rs:2489
#35 scheduled_thread_pool::{impl#7}::new_inner::{closure#0} () at src/lib.rs:158
#36 core::option::Option::map<&str, alloc::string::String, scheduled_thread_pool::{impl#7}::new_inner::{closure_env#0}> () at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/option.rs:929
#37 scheduled_thread_pool::ScheduledThreadPool::new_inner () at src/lib.rs:158
#38 0x000055fe67742f14 in moka::common::concurrent::thread_pool::ThreadPool::new () at src/common/concurrent/thread_pool.rs:38
#39 moka::common::concurrent::thread_pool::{impl#3}::acquire_pool::{closure#0} () at src/common/concurrent/thread_pool.rs:78
#40 std::collections::hash::map::Entry::or_insert_with<moka::common::concurrent::thread_pool::PoolName, alloc::sync::Arc<moka::common::concurrent::thread_pool::ThreadPool>, moka::common::concurrent::thread_pool::{impl#3}::acquire_pool::{closure_env#0}> ()
    at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/collections/hash/map.rs:2549
#41 moka::common::concurrent::thread_pool::ThreadPoolRegistry::acquire_pool () at src/common/concurrent/thread_pool.rs:73
#42 0x000055fe6772ef5b in moka::common::concurrent::housekeeper::ThreadPoolHousekeeper::new<moka::sync_base::base_cache::Inner<alloc::string::String, alloc::string::String, std::collections::hash::map::RandomState>> () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/moka-0.9.4/src/common/concurrent/housekeeper.rs:242
#43 moka::common::concurrent::housekeeper::Housekeeper::new<moka::sync_base::base_cache::Inner<alloc::string::String, alloc::string::String, std::collections::hash::map::RandomState>> () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/moka-0.9.4/src/common/concurrent/housekeeper.rs:73
#44 0x000055fe677383f8 in moka::sync_base::base_cache::BaseCache::new<alloc::string::String, alloc::string::String, std::collections::hash::map::RandomState> () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/moka-0.9.4/src/sync_base/base_cache.rs:185
#45 0x000055fe6772ab9b in moka::sync::cache::Cache::with_everything<alloc::string::String, alloc::string::String, std::collections::hash::map::RandomState> () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/moka-0.9.4/src/sync/cache.rs:856
#46 0x000055fe67725e42 in moka::sync::builder::CacheBuilder::build<alloc::string::String, alloc::string::String> () at /home/cstrahan/.cargo/registry/src/github.com-1ecc6299db9ec823/moka-0.9.4/src/sync/builder.rs:141
#47 0x000055fe6772b530 in jemalloc_test::main () at src/main.rs:13
cstrahan-blueshift commented 2 years ago

I can no longer reproduce this if I replace parking_lot::Mutex with std::sync::Mutex:

diff --git a/src/lib.rs b/src/lib.rs
index 90223a2..b20aaca 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -363,7 +363,6 @@

 use backtrace::SymbolName;
 use lazy_static::lazy_static;
-use parking_lot::Mutex;
 use rustc_hash::FxHashMap;
 use serde::Serialize;
 use std::alloc::{GlobalAlloc, Layout, System};
@@ -373,6 +372,7 @@ use std::hash::{Hash, Hasher};
 use std::io::BufWriter;
 use std::ops::AddAssign;
 use std::path::{Path, PathBuf};
+use std::sync::Mutex;
 use std::time::{Duration, Instant};
 use thousands::Separable;

@@ -1115,7 +1115,7 @@ impl ProfilerBuilder {
         let ignore_allocs = IgnoreAllocs::new();
         std::assert!(!ignore_allocs.was_already_ignoring_allocs);

-        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
         match phase {
             Phase::Ready => {
                 let file_name = if let Some(file_name) = self.file_name {
@@ -1218,7 +1218,7 @@ unsafe impl GlobalAlloc for Alloc {
         if ignore_allocs.was_already_ignoring_allocs {
             System.alloc(layout)
         } else {
-            let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+            let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
             let ptr = System.alloc(layout);
             if ptr.is_null() {
                 return ptr;
@@ -1242,7 +1242,7 @@ unsafe impl GlobalAlloc for Alloc {
         if ignore_allocs.was_already_ignoring_allocs {
             System.realloc(old_ptr, layout, new_size)
         } else {
-            let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+            let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
             let new_ptr = System.realloc(old_ptr, layout, new_size);
             if new_ptr.is_null() {
                 return new_ptr;
@@ -1284,7 +1284,7 @@ unsafe impl GlobalAlloc for Alloc {
         if ignore_allocs.was_already_ignoring_allocs {
             System.dealloc(ptr, layout)
         } else {
-            let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+            let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
             System.dealloc(ptr, layout);

             if let Phase::Running(g @ Globals { heap: Some(_), .. }) = phase {
@@ -1320,7 +1320,7 @@ pub fn ad_hoc_event(weight: usize) {
     let ignore_allocs = IgnoreAllocs::new();
     std::assert!(!ignore_allocs.was_already_ignoring_allocs);

-    let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+    let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
     if let Phase::Running(g @ Globals { heap: None, .. }) = phase {
         let bt = new_backtrace!(g);
         let pp_info_idx = g.get_pp_info(bt, PpInfo::new_ad_hoc);
@@ -1335,7 +1335,7 @@ impl Profiler {
         let ignore_allocs = IgnoreAllocs::new();
         std::assert!(!ignore_allocs.was_already_ignoring_allocs);

-        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
         match std::mem::replace(phase, Phase::Ready) {
             Phase::Ready => unreachable!(),
             Phase::Running(g) => {
@@ -1637,7 +1637,7 @@ impl HeapStats {
         let ignore_allocs = IgnoreAllocs::new();
         std::assert!(!ignore_allocs.was_already_ignoring_allocs);

-        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
         match phase {
             Phase::Ready => {
                 panic!("dhat: getting heap stats when no profiler is running")
@@ -1661,7 +1661,7 @@ impl AdHocStats {
         let ignore_allocs = IgnoreAllocs::new();
         std::assert!(!ignore_allocs.was_already_ignoring_allocs);

-        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+        let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
         match phase {
             Phase::Ready => {
                 panic!("dhat: getting ad hoc stats when no profiler is running")
@@ -1687,7 +1687,7 @@ where
     let ignore_allocs = IgnoreAllocs::new();
     std::assert!(!ignore_allocs.was_already_ignoring_allocs);

-    let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock();
+    let phase: &mut Phase<Globals> = &mut TRI_GLOBALS.lock().unwrap();
     match phase {
         Phase::Ready => panic!("dhat: asserting when no profiler is running"),
         Phase::Running(g) => {

So now I'm wondering if this is a bug in parking_lot? :thinking:

cstrahan-blueshift commented 2 years ago

Tried using my modified dhat source tree (as described in my last comment) in my real-world project, and it ran successfully (whereas I was never able to get it to run successfully on any attempt with the parking_lot Mutex).

Would you accept a PR that puts the choice of locking library behind a feature? Could make parking_lot a default feature for backwards compat, I suppose.

I suppose you'll probably also want to probe a little bit from your end first. Lemme know if there's anything I can do to help.

Thanks! :smile:

cstrahan-blueshift commented 2 years ago

Got response from @Amanieu:

I think you are hitting the same issue as https://github.com/Amanieu/parking_lot/pull/305, for which there is no real good solution. The problem is that parking_lot itself needs to allocate memory, which is a problem if the allocator uses parking_lot.

@nnethercote should we switch tostd::sync::Mutex then?

nnethercote commented 2 years ago

Thanks for this PR. I ended up going with a different fix for the deadlock problems, https://github.com/nnethercote/dhat-rs/pull/24, which uses mintex, a minimal mutex implementation that is guaranteed to not allocate, and which uses the parking_lot API, which was ideal for DHAT. Try it out in release 0.3.2.