search

nnethercote / dhat-rs

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

Assertion failures and double free when integrating dhat into rust-analyzer #4

Closed jonas-schievink closed 3 years ago

jonas-schievink commented 3 years ago

After applying this patch to https://github.com/rust-analyzer/rust-analyzer/commit/3df4b8c1fa4c1686228162bff03e4db3f01b9826:

diff --git a/crates/rust-analyzer/Cargo.toml b/crates/rust-analyzer/Cargo.toml
index 039976e4b..66f395518 100644
--- a/crates/rust-analyzer/Cargo.toml
+++ b/crates/rust-analyzer/Cargo.toml
@@ -31,6 +31,7 @@ serde_json = { version = "1.0.48", features = ["preserve_order"] }
 threadpool = "1.7.1"
 rayon = "1.5"
 mimalloc = { version = "0.1.19", default-features = false, optional = true }
+dhat = { version = "0.1.1", optional = true }
 lsp-server = "0.5.0"
 tracing = "0.1"
 tracing-subscriber = { version = "0.2", default-features = false, features = ["env-filter", "registry"] }
diff --git a/crates/rust-analyzer/src/bin/main.rs b/crates/rust-analyzer/src/bin/main.rs
index defdcbd74..5c6502d63 100644
--- a/crates/rust-analyzer/src/bin/main.rs
+++ b/crates/rust-analyzer/src/bin/main.rs
@@ -19,7 +19,14 @@ use vfs::AbsPathBuf;
 #[global_allocator]
 static ALLOC: mimalloc::MiMalloc = mimalloc::MiMalloc;

+#[cfg(feature = "dhat")]
+#[global_allocator]
+static ALLOC: dhat::DhatAlloc = dhat::DhatAlloc;
+
 fn main() {
+    #[cfg(feature = "dhat")]
+    let _dhat = dhat::Dhat::start_heap_profiling();
+
     if let Err(err) = try_main() {
         eprintln!("{}", err);
         process::exit(101);

Running this command:

cd crates/rust-analyzer
cargo run --bin rust-analyzer --release --features=dhat -- analysis-stats --quiet --memory-usage ../..

...results in different panics and assertion failures:

Assertion failure and double free ``` thread '' panicked at 'assertion failed: matches!(old, None)', /home/jonas/.cargo/registry/src/github.com-1ecc6299db9ec823/dhat-0.1.1/src/lib.rs:301:17 stack backtrace: 0: std::panicking::begin_panic 1: std::thread::local::LocalKey::with 2: ::realloc 3: alloc::alloc::realloc at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/alloc.rs:110 4: alloc::alloc::Global::grow_impl at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/alloc.rs:185 5: ::grow at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/alloc.rs:237 6: alloc::raw_vec::finish_grow at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:491 7: alloc::raw_vec::RawVec::grow_amortized at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:427 8: alloc::raw_vec::RawVec::try_reserve at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:316 9: alloc::raw_vec::RawVec::reserve at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:310 10: alloc::vec::Vec::reserve at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:505 11: alloc::vec::Vec::append_elements at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:1270 12: as alloc::vec::SpecExtend<&T,core::slice::iter::Iter>>::spec_extend at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:2416 13: alloc::vec::Vec::extend_from_slice at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:1601 14: std::sys_common::os_str_bytes::Buf::push_slice at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/os_str_bytes.rs:128 15: std::ffi::os_str::OsString::push at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/ffi/os_str.rs:167 16: std::path::PathBuf::_push at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:1181 17: std::path::PathBuf::push at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:1152 18: std::path::Path::_join at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:2145 19: std::path::Path::join at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:2140 20: std::sys::unix::fs::DirEntry::path at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys/unix/fs.rs:500 21: std::fs::DirEntry::path at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/fs.rs:1382 22: walkdir::dent::DirEntry::from_entry 23: ::next 24: as core::iter::traits::iterator::Iterator>::next 25: as alloc::vec::SpecExtend>::spec_extend 26: vfs_notify::NotifyActor::run note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. free(): double free detected in tcache 2 thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "PoisonError { inner: .. }"', /home/jonas/.cargo/registry/src/github.com-1ecc6299db9ec823/dhat-0.1.1/src/lib.rs:fish: “cargo run --bin rust-analyzer -…” terminated by signal SIGABRT (Abort) ```
Double (triple?) panic ``` thread '' panicked at 'assertion failed: matches!(old, None)', /home/jonas/.cargo/registry/src/github.com-1ecc6299db9ec823/dhat-0.1.1/src/lib.rs:301:17 stack backtrace: 0: std::panicking::begin_panic 1: std::thread::local::LocalKey::with 2: ::realloc 3: alloc::alloc::realloc at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/alloc.rs:110 4: alloc::alloc::Global::grow_impl at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/alloc.rs:185 5: ::grow at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/alloc.rs:237 6: alloc::raw_vec::finish_grow at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:491 7: alloc::raw_vec::RawVec::grow_amortized at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:427 8: alloc::raw_vec::RawVec::try_reserve at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:316 9: alloc::raw_vec::RawVec::reserve at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/raw_vec.rs:310 10: alloc::vec::Vec::reserve at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:505 11: alloc::vec::Vec::append_elements at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:1270 12: as alloc::vec::SpecExtend<&T,core::slice::iter::Iter>>::spec_extend at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:2416 13: alloc::vec::Vec::extend_from_slice at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/vec.rs:1601 14: std::sys_common::os_str_bytes::Buf::push_slice at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/os_str_bytes.rs:128 15: std::ffi::os_str::OsString::push at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/ffi/os_str.rs:167 16: std::path::PathBuf::_push at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:1181 17: std::path::PathBuf::push at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:1152 18: std::path::Path::_join at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:2145 19: std::path::Path::join at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/path.rs:2140 20: std::sys::unix::fs::DirEntry::path at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys/unix/fs.rs:500 21: std::fs::DirEntry::path at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/fs.rs:1382 22: walkdir::dent::DirEntry::from_entry 23: ::next 24: as core::iter::traits::iterator::Iterator>::next 25: as alloc::vec::SpecExtend>::spec_extend 26: vfs_notify::NotifyActor::run note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "PoisonError { inner: .. }"', /home/jonas/.cargo/registry/src/github.com-1ecc6299db9ec823/dhat-0.1.1/src/lib.rs:316:66 stack backtrace: 0: rust_begin_unwind at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:483 1: core::panicking::panic_fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/panicking.rs:85 2: core::option::expect_none_failed at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/option.rs:1234 3: std::thread::local::LocalKey::with 4: ::dealloc 5: vfs::path_interner::PathInterner::intern 6: vfs::Vfs::set_file_contents 7: rust_analyzer::cli::load_cargo::load_cargo 8: rust_analyzer::cli::analysis_stats::AnalysisStatsCmd::run 9: rust_analyzer::main note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', /home/jonas/.cargo/registry/src/github.com-1ecc6299db9ec823/dhat-0.1.1/src/lib.rs:542:15 stack backtrace: 0: 0x56081e718f10 - std::backtrace_rs::backtrace::libunwind::trace::h72c2fb8038f1bbee at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/../../backtrace/src/backtrace/libunwind.rs:96 1: 0x56081e718f10 - std::backtrace_rs::backtrace::trace_unsynchronized::h1e3b084883f1e78c at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/../../backtrace/src/backtrace/mod.rs:66 2: 0x56081e718f10 - std::sys_common::backtrace::_print_fmt::h3bf6a7ebf7f0394a at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:79 3: 0x56081e718f10 - ::fmt::h2e8cb764b7fe02e7 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:58 4: 0x56081e74006c - core::fmt::write::h7a1184eaee6a8644 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/fmt/mod.rs:1080 5: 0x56081e712a62 - std::io::Write::write_fmt::haeeb374d93a67eac at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/io/mod.rs:1516 6: 0x56081e71b40d - std::sys_common::backtrace::_print::h1d14a7f6ad632dc8 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:61 7: 0x56081e71b40d - std::sys_common::backtrace::print::h301abac8bb2e3e81 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:48 8: 0x56081e71b40d - std::panicking::default_hook::{{closure}}::hde0cb80358a6920a at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:208 9: 0x56081e71b0b8 - std::panicking::default_hook::h9b1a691049a0ec8f at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:227 10: 0x56081e71baf1 - std::panicking::rust_panic_with_hook::h2bdec87b60580584 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:577 11: 0x56081e71b699 - std::panicking::begin_panic_handler::{{closure}}::h101ca09d9df5db47 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:484 12: 0x56081e71937c - std::sys_common::backtrace::__rust_end_short_backtrace::h3bb85654c20113ca at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:153 13: 0x56081e71b659 - rust_begin_unwind at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:483 14: 0x56081e73dc61 - core::panicking::panic_fmt::h48c31e1e3d550146 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/panicking.rs:85 15: 0x56081e73dbad - core::panicking::panic::h184ede6dd822ffb4 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/panicking.rs:50 16: 0x56081da9a2cd - ::drop::h0a45d9344a935abe 17: 0x56081da00665 - rust_analyzer::main::hb8a869c11f5a510f 18: 0x56081d9f9c73 - std::sys_common::backtrace::__rust_begin_short_backtrace::h4fe9e15942c2cdb2 19: 0x56081da05059 - std::rt::lang_start::{{closure}}::h1812fd355e84b98b 20: 0x56081e71c007 - core::ops::function::impls:: for &F>::call_once::he179d32a5d10d957 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/ops/function.rs:259 21: 0x56081e71c007 - std::panicking::try::do_call::hcb3d5e7be089b2b4 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:381 22: 0x56081e71c007 - std::panicking::try::h7ac93b0cd56fb701 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:345 23: 0x56081e71c007 - std::panic::catch_unwind::h7b40e396c93a4fcd at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panic.rs:382 24: 0x56081e71c007 - std::rt::lang_start_internal::h142b9cc66267fea1 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:51 25: 0x56081da00732 - main 26: 0x7f5d70414152 - __libc_start_main 27: 0x56081d9c90ae - _start 28: 0x0 - thread panicked while panicking. aborting. ```

Any idea what I could have unearthed here?

nnethercote commented 3 years ago

When realloc is called, an allocation is moved from old_ptr to new_ptr, but dhat-rs thinks that there is already an allocation at new_ptr. This is impossible (assuming the allocator isn't buggy), so there must be a problem with dhat-rs's recording of allocations.

Here's how I would debug this:

Note: all three of the eprintln! statements must be within the ignore_allocs closure.

jonas-schievink commented 3 years ago 
ThreadId(1) alloc 0x55e8c4282b10 (Layout { size_: 4, align_: 1 })
ThreadId(1) realloc 0x55e8c4282b10 -> 0x55e8c4282b10 (Layout { size_: 4, align_: 1 })
ThreadId(1) alloc 0x55e8c4282ba0 (Layout { size_: 48, align_: 8 })
ThreadId(1) alloc 0x55e8c4282be0 (Layout { size_: 15, align_: 1 })
ThreadId(1) dealloc 0x55e8c4282be0 (Layout { size_: 15, align_: 1 })
thread '<unnamed>' panicked at 'assertion failed: c.borrow().is_none()', library/std/src/sys_common/thread_info.rs:40:26
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
ThreadId(1) alloc 0x55e8c4282be0 (Layout { size_: 16, align_: 8 })
ThreadId(1) alloc 0x55e8c4282c00 (Layout { size_: 80, align_: 8 })
fatal runtime error: failed to initiate panic, error 5

https://github.com/rust-lang/rust/blob/3f2088aa603d2cd3f43c20795872de9cd6ec7735/library/std/src/sys_common/thread_info.rs#L40

This makes no sense, wow

jonas-schievink commented 3 years ago 
(a lot of unrelated operations)
realloc 0x7f60f00930c0 -> 0x7f60f00b28c0 (Layout { size_: 1536, align_: 8 }, new size = 3072)
(a lot of unrelated operations)
realloc 0x7f60f000ff40 -> 0x7f60f00b28c0 (Layout { size_: 76, align_: 1 }, new size = 152)
thread '<unnamed>' panicked at '0x7f60f00b28c0', /home/jonas/dev/dhat-rs/src/lib.rs:315:17
stack backtrace:
dealloc 0x7f60f00b28c0 (Layout { size_: 3072, align_: 8 })
   0: rust_begin_unwind
             at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:483
   1: std::panicking::begin_panic_fmt
             at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:437
   2: dhat::ignore_allocs
   3: <dhat::DhatAlloc as core::alloc::global::GlobalAlloc>::realloc
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

It seems that the assertion is failing correctly, but I have no idea why this would happen.

nnethercote commented 3 years ago

I can reproduce this. There is some randomness to it. Sometimes it asserts within Dhat::realloc, sometimes it asserts on the equivalent assertion within Dhat::alloc. I did three runs with eprintln!s in it. The first and third runs hit the assertion failure after 169,588 and 162,800 lines of output, respectively; the second run didn't have any problems and I interrupted it after 2,202,676 lines of output.

Partial output from the first run, which asserted in Dhat::realloc:

realloc 0x7f9dc146ee80 Layout { size_: 43, align_: 1 } 86 -> 0x7f9dc143cbf0
...
realloc 0x7f9dc146ee80 Layout { size_: 46, align_: 1 } 92 -> 0x7f9dc143cbf0
thread 'dealloc 0x7f9dc143cbf0 Layout { size_: 86, align_: 1 }
<unnamed>' panicked at 'assertion failed: matches!(old, None)', /Users/njn/moz/dhat-rs/src/lib.rs:317:17

Partial output from the first run, which asserted in Dhat::alloc:

alloc Layout { size_: 81, align_: 1 } -> 0x7fa957d44da0
...
alloc Layout { size_: 100, align_: 1 } -> 0x7fa957d44da0
dealloc 0x7fa957d44da0 Layout { size_thread ': 81, align_: 1 }
main' panicked at 'assertion failed: matches!(old, None)', /Users/njn/moz/dhat-rs/src/lib.rs:270:17

In both cases (and in your output above) the panic output is interleaved with output from a dealloc. And in all cases, if that dealloc took place one operation earlier, then the alloc/realloc would be ok. This makes me suspicious. Something smells racy, but I'm not sure if it's in dhat-rs, or whether dhat-rs is exposing some pre-existing race...

nnethercote commented 3 years ago

Hmm, the above may be a red herring, because I put my eprintln! statements outside of getting the global lock.

realloc is complex and often a cause of bugs so I tried commenting out Dhat::realloc—which is legit because it is a provided method—but I still get assertion failures within Dhat::alloc, so it's not a realloc-specific bug.

nnethercote commented 3 years ago

Aha, the data race idea is not a red herring. There is insufficient atomicity within Dhat's methods. So it's possible to have a sequence like this:

I have a draft patch that fixes things and seems to avoid the problem. I will clean it up and merge it later today.