Block cell size is sometimes zero in native MarkSweep

[wks]

This bug is observed in the CI for a PR, but is reproducible on the master branch. https://github.com/mmtk/mmtk-core/actions/runs/8548408967/job/23453824271?pr=1067

The bug manifests as GC hanging during the first GC, with 100% CPU usage.

The bug is related to the native MarkSweep plan and eager sweeping. The "eager_sweeping" feature must be enabled to trigger this bug. The "vo_bit" feature implies "eager_sweeping".

To reproduce this bug, we need to compile mmtk-openjdk with VO-bit enabled (which will enable "eager_sweeping").

export DEBUG_LEVEL=fastdebug
make CONF=linux-x86_64-normal-server-$DEBUG_LEVEL THIRD_PARTY_HEAP=$PWD/../mmtk-openjdk/openjdk MMTK_VO_BIT=1

One benchmark that is know to reproduce this error is antlr in dacapo-2006-10-MR2.jar, with the following command line:

MMTK_THREADS=128 MMTK_PLAN=MarkSweep /path/to/openjdk/build/linux-x86_64-normal-server-fastdebug/jdk/bin/java -XX:+UseThirdPartyHeap -server -XX:MetaspaceSize=100M -Xms40M -Xmx40M -jar dacapo-2006-10-MR2.jar antlr

When the error occurs, it will hang during the very first GC.

Here is a backtrace captured using GDB:

#0  0x00007ffff5414956 in mmtk::util::metadata::side_metadata::helpers::meta_byte_mask (metadata_spec=0x7ffff5a6a508)
    at src/util/metadata/side_metadata/helpers.rs:135
#1  0x00007ffff5459b5b in mmtk::util::metadata::side_metadata::global::{impl#0}::store_atomic::{closure#0}<u8> ()
    at src/util/metadata/side_metadata/global.rs:592
#2  0x00007ffff5458c78 in mmtk::util::metadata::side_metadata::global::SideMetadataSpec::side_metadata_access<u8, (), mmtk::util::metadata::side_metadata::global::{impl#0}::store_atomic::{closure_env#0}<u8>, mmtk::util::metadata::side_metadata::global::{impl#0}::store_atomic::{closure_env#1}<u8>> (self=0x7ffff5a6a508, data_addr=..., input=..., access_func=..., verify_func=...)
    at src/util/metadata/side_metadata/global.rs:483
#3  0x00007ffff5459908 in mmtk::util::metadata::side_metadata::global::SideMetadataSpec::store_atomic<u8> (self=0x7ffff5a6a508,
    data_addr=..., metadata=0, order=core::sync::atomic::Ordering::SeqCst) at src/util/metadata/side_metadata/global.rs:584
#4  0x00007ffff512b3ca in mmtk::util::metadata::vo_bit::unset_vo_bit_nocheck<mmtk_openjdk::OpenJDK<true>> (object=...)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/util/metadata/vo_bit/mod.rs:81
#5  0x00007ffff5188066 in mmtk::policy::marksweepspace::native_ms::block::Block::simple_sweep<mmtk_openjdk::OpenJDK<true>> (
    self=0x7fff839f2580)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/policy/marksweepspace/native_ms/block.rs:298
#6  0x00007ffff51899af in mmtk::policy::marksweepspace::native_ms::block::Block::sweep<mmtk_openjdk::OpenJDK<true>> (
    self=0x7fff839f2580)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/policy/marksweepspace/native_ms/block.rs:273
#7  0x00007ffff51a91be in mmtk::policy::marksweepspace::native_ms::block_list::BlockList::sweep_blocks<mmtk_openjdk::OpenJDK<true>>
    (self=0x7ffff02ceea0, space=0x7ffff02c83f0)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/policy/marksweepspace/native_ms/block_list.rs:171
#8  0x00007ffff518601e in mmtk::util::alloc::free_list_allocator::FreeListAllocator<mmtk_openjdk::OpenJDK<true>>::reset<mmtk_openjdk::OpenJDK<true>> (self=0x7ffff0032ca8)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/util/alloc/free_list_allocator.rs:467
#9  0x00007ffff51865aa in mmtk::util::alloc::free_list_allocator::FreeListAllocator<mmtk_openjdk::OpenJDK<true>>::release<mmtk_openjdk::OpenJDK<true>> (self=0x7ffff0032ca8)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/util/alloc/free_list_allocator.rs:422
#10 0x00007ffff5136d5b in mmtk::plan::marksweep::mutator::native_mark_sweep::ms_mutator_release<mmtk_openjdk::OpenJDK<true>> (
    mutator=0x7ffff0032ae8, _tls=...)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/plan/marksweep/mutator.rs:78
#11 0x00007ffff536c850 in core::ops::function::Fn::call<fn(&mut mmtk::plan::mutator_context::Mutator<mmtk_openjdk::OpenJDK<true>>, mmtk::util::opaque_pointer::VMWorkerThread), (&mut mmtk::plan::mutator_context::Mutator<mmtk_openjdk::OpenJDK<true>>, mmtk::util::opaque_pointer::VMWorkerThread)> () at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:79
#12 0x00007ffff5294fd9 in mmtk::plan::mutator_context::{impl#1}::release<mmtk_openjdk::OpenJDK<true>> (self=0x7ffff0032ae8,
    tls=...) at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/plan/mutator_context.rs:105
#13 0x00007ffff51bad52 in mmtk::scheduler::gc_work::{impl#11}::do_work<mmtk_openjdk::OpenJDK<true>> (self=0x7ffedc00b980,
    worker=0x7ffff0583bd0,
    _mmtk=0x7ffff5ad9010 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/scheduler/gc_work.rs:172
#14 0x00007ffff51fbe9d in mmtk::scheduler::work::GCWork::do_work_with_stat<mmtk::scheduler::gc_work::ReleaseMutator<mmtk_openjdk::OpenJDK<true>>, mmtk_openjdk::OpenJDK<true>> (self=0x7ffedc00b980, worker=0x7ffff0583bd0,
    mmtk=0x7ffff5ad9010 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/scheduler/work.rs:45
#15 0x00007ffff53b8146 in mmtk::scheduler::worker::GCWorker<mmtk_openjdk::OpenJDK<true>>::run<mmtk_openjdk::OpenJDK<true>> (
    self=0x7ffff0583bd0, tls=...,
    mmtk=0x7ffff5ad9010 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/scheduler/worker.rs:244
#16 0x00007ffff50c6395 in mmtk::memory_manager::start_worker<mmtk_openjdk::OpenJDK<true>> (
    mmtk=0x7ffff5ad9010 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>, tls=...,
--Type <RET> for more, q to quit, c to continue without paging--
    worker=0x7ffff0583bd0) at /home/wks/projects/mmtk-github/parallels/feature/fork/mmtk-core/src/memory_manager.rs:470
#17 0x00007ffff53ca7be in mmtk_openjdk::api::start_worker (tls=..., worker=0x7ffff0583bd0) at src/api.rs:210
#18 0x00007ffff7553f47 in Thread::call_run (this=0x7ffff061b800)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/openjdk/src/hotspot/share/runtime/thread.cpp:402
#19 0x00007ffff72403e6 in thread_native_entry (thread=0x7ffff061b800)
    at /home/wks/projects/mmtk-github/parallels/feature/fork/openjdk/src/hotspot/os/linux/os_linux.cpp:826
#20 0x00007ffff7df455a in ?? () from /usr/lib/libc.so.6
#21 0x00007ffff7e71a3c in ?? () from /usr/lib/libc.so.6

Frame 0-4 are not important. The problem lies in frame 5. Inside the function Block::simple_sweep, the variable cell_size can sometimes be 0. If this happens, the following while loop will never exit.

    fn simple_sweep<VM: VMBinding>(&self) {
        let cell_size = self.load_block_cell_size(); // This may be zero.
        let mut cell = self.start();
        // ...
        while cell + cell_size <= self.start() + Block::BYTES {
            // ...
            cell += cell_size; // If `cell_size` is 0, `cell` will be stuck at the same value forever.
        }

        self.store_free_list(last);
    }

Presumably, the cell size should never be zero. If the cell size is zero, it means the block is either uninitialized, or there is a race such that another thread overwrote the block size to 0 before the current thread attempts to sweep it.

I have not found the root cause, yet, but the following patch can help us reproduce the error. The debug_assert_ne will make it panic immediately if the block size is zero, and the std::process::exit(0); statement will make the program exit earlier because the error is known to occur during the first GC.

Patch:

diff --git a/src/policy/marksweepspace/native_ms/block.rs b/src/policy/marksweepspace/native_ms/block.rs
index 625a82d85..57f64ce1f 100644
--- a/src/policy/marksweepspace/native_ms/block.rs
+++ b/src/policy/marksweepspace/native_ms/block.rs
@@ -188,6 +188,7 @@ impl Block {
     }
 
     pub fn store_block_cell_size(&self, size: usize) {
+        debug_assert_ne!(size, 0);
         unsafe { Block::SIZE_TABLE.store::<usize>(self.start(), size) }
     }
 
@@ -282,6 +283,7 @@ impl Block {
     /// that we need to use this method correctly.
     fn simple_sweep<VM: VMBinding>(&self) {
         let cell_size = self.load_block_cell_size();
+        debug_assert_ne!(cell_size, 0);
         let mut cell = self.start();
         let mut last = unsafe { Address::zero() };
         while cell + cell_size <= self.start() + Block::BYTES {
diff --git a/src/scheduler/controller.rs b/src/scheduler/controller.rs
index 3608f1ebf..df9a0fe6f 100644
--- a/src/scheduler/controller.rs
+++ b/src/scheduler/controller.rs
@@ -143,6 +143,9 @@ impl<VM: VMBinding> GCController<VM> {
         };
         end_of_gc.do_work_with_stat(&mut self.coordinator_worker, self.mmtk);
 
+        println!("First GC finished without error.");
+        std::process::exit(0);
+
         self.scheduler.debug_assert_all_buckets_deactivated();
     }
 }
diff --git a/src/util/alloc/free_list_allocator.rs b/src/util/alloc/free_list_allocator.rs
index 50ce36bd2..1b9abde54 100644
--- a/src/util/alloc/free_list_allocator.rs
+++ b/src/util/alloc/free_list_allocator.rs
@@ -333,6 +333,7 @@ impl<VM: VMBinding> FreeListAllocator<VM> {
     }
 
     fn init_block(&self, block: Block, cell_size: usize) {
+        debug_assert_ne!(cell_size, 0);
         self.space.record_new_block(block);
 
         // construct free list

Then use the following command to repeat the experiment:

while MMTK_THREADS=128 MMTK_PLAN=MarkSweep ~/projects/mmtk-github/openjdk/build/linux-x86_64-normal-server-fastdebug/jdk/bin/java -XX:+UseThirdPartyHeap -server -XX:MetaspaceSize=100M -Xms40M -Xmx40M -jar dacapo-2006-10-MR2.jar antlr; do true; done

It will need about 30-40 attempts before it panics.

[qinsoon]

This might be related with #824 (comment). I am debugging JikesRVM, and there seems to be some issues about side metadata in mark sweep as well (without eager_sweep).

[wks]

It panics in simple_sweep. Since my patch also makes it panic when storing 0 into the cell size metadata (and it didn't panic there), I believe the 0 value that simple_sweep loaded from the cell size metadata was an uninitialized value. Then the question becomes why it tried to sweep an uninitialized block in the first place.

[wks]

Here are the two stack traces.

When the block cell size is set to 0:

#0  core::sync::atomic::atomic_store<u64> (dst=0x4e9682020ce0, val=0, order=core::sync::atomic::Ordering::SeqCst)
    at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/sync/atomic.rs:3280
#1  0x000075e9b323e7d2 in core::sync::atomic::AtomicU64::store (self=0x4e9682020ce0, val=0,
    order=core::sync::atomic::Ordering::SeqCst)
    at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/sync/atomic.rs:2428
#2  0x000075e9b323b395 in mmtk::util::metadata::metadata_val_traits::{impl#13}::store_atomic (addr=..., value=0,
    order=core::sync::atomic::Ordering::SeqCst) at src/util/metadata/metadata_val_traits.rs:156
#3  0x000075e9b3201f1b in mmtk::util::metadata::side_metadata::global::{impl#0}::store_atomic::{closure#0}<u64> ()
    at src/util/metadata/side_metadata/global.rs:601
#4  0x000075e9b32009de in mmtk::util::metadata::side_metadata::global::SideMetadataSpec::side_metadata_access<u64, (), mmtk::util::metadata::side_metadata::global::{impl#0}::store_atomic::{closure_env#0}<u64>, mmtk::util::metadata::side_metadata::global::{impl#0}::store_atomic::{closure_env#1}<u64>> (self=0x75e9471fe5b0, data_addr=..., input=..., access_func=..., verify_func=...)
    at src/util/metadata/side_metadata/global.rs:483
#5  0x000075e9b3201a09 in mmtk::util::metadata::side_metadata::global::SideMetadataSpec::store_atomic<u64> (self=0x75e9471fe5b0,
    data_addr=..., metadata=0, order=core::sync::atomic::Ordering::SeqCst) at src/util/metadata/side_metadata/global.rs:584
#6  0x000075e9b322ae8d in mmtk::util::metadata::side_metadata::global::SideMetadataSpec::set_zero_atomic (self=0x75e9471fe5b0,
    data_addr=..., order=core::sync::atomic::Ordering::SeqCst) at src/util/metadata/side_metadata/global.rs:640
#7  0x000075e9b2f92a65 in mmtk::policy::marksweepspace::native_ms::global::MarkSweepSpace<mmtk_openjdk::OpenJDK<true>>::block_clear_metadata<mmtk_openjdk::OpenJDK<true>> (self=0x75e9ac2c8370, block=...)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/global.rs:307
#8  0x000075e9b2f927bd in mmtk::policy::marksweepspace::native_ms::global::MarkSweepSpace<mmtk_openjdk::OpenJDK<true>>::release_block<mmtk_openjdk::OpenJDK<true>> (self=0x75e9ac2c8370, block=...)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/global.rs:299
#9  0x000075e9b316c48b in mmtk::policy::marksweepspace::native_ms::block::Block::attempt_release<mmtk_openjdk::OpenJDK<true>> (
    self=..., space=0x75e9ac2c8370)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/block.rs:240
#10 0x000075e9b2f911cc in mmtk::policy::marksweepspace::native_ms::global::{impl#5}::do_work<mmtk_openjdk::OpenJDK<true>> (
    self=0x75e924033f60, _worker=0x75e9ac455da0,
    _mmtk=0x75e9b38ae050 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/global.rs:371
#11 0x000075e9b2f9983f in mmtk::scheduler::work::GCWork::do_work_with_stat<mmtk::policy::marksweepspace::native_ms::global::SweepChunk<mmtk_openjdk::OpenJDK<true>>, mmtk_openjdk::OpenJDK<true>> (self=0x75e924033f60, worker=0x75e9ac455da0,
    mmtk=0x75e9b38ae050 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/scheduler/work.rs:45
#12 0x000075e9b315fb30 in mmtk::scheduler::worker::GCWorker<mmtk_openjdk::OpenJDK<true>>::run<mmtk_openjdk::OpenJDK<true>> (
    self=0x75e9ac455da0, tls=...,
    mmtk=0x75e9b38ae050 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/scheduler/worker.rs:244
#13 0x000075e9b30fdd55 in mmtk::memory_manager::start_worker<mmtk_openjdk::OpenJDK<true>> (
    mmtk=0x75e9b38ae050 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>, tls=...,
    worker=0x75e9ac455da0) at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/memory_manager.rs:470
#14 0x000075e9b301f3e8 in mmtk_openjdk::api::start_worker (tls=..., worker=0x75e9ac455da0) at src/api.rs:210
#15 0x000075e9b5353f47 in Thread::call_run (this=0x75e9ac476800)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/openjdk/src/hotspot/share/runtime/thread.cpp:402
#16 0x000075e9b50403e6 in thread_native_entry (thread=0x75e9ac476800)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/openjdk/src/hotspot/os/linux/os_linux.cpp:826
#17 0x000075e9b5c0955a in ?? () from /usr/lib/libc.so.6
#18 0x000075e9b5c86874 in clone () from /usr/lib/libc.so.6

When simple_sweep happens:

#0  0x000075e9b5c0b32c in ?? () from /usr/lib/libc.so.6
#1  0x000075e9b5bba6c8 in raise () from /usr/lib/libc.so.6
#2  0x000075e9b5ba24b8 in abort () from /usr/lib/libc.so.6
#3  0x000075e9b3619d27 in std::sys::pal::unix::abort_internal () at library/std/src/sys/pal/unix/mod.rs:372
#4  0x000075e9b3616439 in std::panicking::rust_panic () at library/std/src/panicking.rs:834
#5  0x000075e9b361621a in std::panicking::rust_panic_with_hook () at library/std/src/panicking.rs:803
#6  0x000075e9b3615f22 in std::panicking::begin_panic_handler::{closure#0} () at library/std/src/panicking.rs:659
#7  0x000075e9b3614a56 in std::sys_common::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::{closure_env#0}, !> () at library/std/src/sys_common/backtrace.rs:171
#8  0x000075e9b3615c74 in std::panicking::begin_panic_handler () at library/std/src/panicking.rs:647
#9  0x000075e9b2ec4ba5 in core::panicking::panic_fmt () at library/core/src/panicking.rs:72
#10 0x000075e9b2ec501b in core::panicking::assert_failed_inner () at library/core/src/panicking.rs:342
#11 0x000075e9b35ede6e in core::panicking::assert_failed<usize, usize> (kind=core::panicking::AssertKind::Ne, left=0x75e974bfe580,
    right=0x75e9b3643838, args=<error reading variable: Cannot access memory at address 0x1>)
    at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/panicking.rs:297
#12 0x000075e9b316c136 in mmtk::policy::marksweepspace::native_ms::block::Block::simple_sweep<mmtk_openjdk::OpenJDK<true>> (
    self=0x75e974bfe660)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/block.rs:286
#13 0x000075e9b316d7fd in mmtk::policy::marksweepspace::native_ms::block::Block::sweep<mmtk_openjdk::OpenJDK<true>> (
    self=0x75e974bfe660)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/block.rs:274
#14 0x000075e9b2f63aba in mmtk::policy::marksweepspace::native_ms::block_list::BlockList::sweep_blocks<mmtk_openjdk::OpenJDK<true>>
    (self=0x75e9ac2cee30, space=0x75e9ac2c8370)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/policy/marksweepspace/native_ms/block_list.rs:171
#15 0x000075e9b300c47c in mmtk::util::alloc::free_list_allocator::FreeListAllocator<mmtk_openjdk::OpenJDK<true>>::reset<mmtk_openjdk::OpenJDK<true>> (self=0x75e9ac0334a8)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/util/alloc/free_list_allocator.rs:467
#16 0x000075e9b300cb5a in mmtk::util::alloc::free_list_allocator::FreeListAllocator<mmtk_openjdk::OpenJDK<true>>::release<mmtk_openjdk::OpenJDK<true>> (self=0x75e9ac0334a8)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/util/alloc/free_list_allocator.rs:422
#17 0x000075e9b2f4eaeb in mmtk::plan::marksweep::mutator::native_mark_sweep::ms_mutator_release<mmtk_openjdk::OpenJDK<true>> (
    mutator=0x75e9ac0332e8, _tls=...)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/plan/marksweep/mutator.rs:78
#18 0x000075e9b3193120 in core::ops::function::Fn::call<fn(&mut mmtk::plan::mutator_context::Mutator<mmtk_openjdk::OpenJDK<true>>, mmtk::util::opaque_pointer::VMWorkerThread), (&mut mmtk::plan::mutator_context::Mutator<mmtk_openjdk::OpenJDK<true>>, mmtk::util::opaque_pointer::VMWorkerThread)> () at /rustc/aedd173a2c086e558c2b66d3743b344f977621a7/library/core/src/ops/function.rs:79
#19 0x000075e9b2f6bf99 in mmtk::plan::mutator_context::{impl#1}::release<mmtk_openjdk::OpenJDK<true>> (self=0x75e9ac0332e8,
    tls=...) at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/plan/mutator_context.rs:105
#20 0x000075e9b2ec6795 in mmtk::scheduler::gc_work::{impl#11}::do_work<mmtk_openjdk::OpenJDK<true>> (self=0x75e9240341a0,
    worker=0x75e9ac4556e0,
    _mmtk=0x75e9b38ae050 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/scheduler/gc_work.rs:172
#21 0x000075e9b2f06b6f in mmtk::scheduler::work::GCWork::do_work_with_stat<mmtk::scheduler::gc_work::ReleaseMutator<mmtk_openjdk::OpenJDK<true>>, mmtk_openjdk::OpenJDK<true>> (self=0x75e9240341a0, worker=0x75e9ac4556e0,
    mmtk=0x75e9b38ae050 <<mmtk_openjdk::SINGLETON_COMPRESSED as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/parallels/fix/malloc-cell0/mmtk-core/src/scheduler/work.rs:45
#22 0x000075e9b315fb30 in mmtk::scheduler::worker::GCWorker<mmtk_openjdk::OpenJDK<true>>::run<mmtk_openjdk::OpenJDK<true>> (

It is a result of two threads calling block.attempt_release() concurrently for the same block. In the stack traces above,

1. In the first thread, SweepChunk::do_work (frame 10) calls Block::attempt_release (frame 9)
2. In the second thread, BlockList::sweep_block (frame 14) has just called Block::attempt_release, and it calls Block::sweep (frame 13).

From the stack trace, the first thread called release_block. It cleared all of its metadata, including the cell size. It also sets the block state to Unallocated.

Then the second thread called Block::attempt_release, and it returned Unallocated. Then the second thread attempted to call Block::sweep on an Unallocated block. I think this is wrong. If a block is unallocated, it's pointless to sweep it.

[wks]

The real race happens between BlockListIterator::next() and Block::attempt_release().

The BlockListIterator stores a "cursor". The "cursor" is the next block to be visited. In BlockListIterator::next(), it caches the next node before returning the current node.

impl Iterator for BlockListIterator {
    type Item = Block;

    fn next(&mut self) -> Option<Self::Item> {
        let ret = self.cursor;
        if let Some(cur) = self.cursor {
            self.cursor = cur.load_next_block(); // It loads the next block in the linked list.
        }
        ret
    }
}

Concurrently, another thread may call Block::attempt_release. It polls the block out of its parent BlockList.

                    let block_list = loop {
                        let list = self.load_block_list();
                        (*list).lock();
                        if list == self.load_block_list() {
                            break list;
                        }
                        (*list).unlock();
                    };
                    (*block_list).remove(self);

The (*list).lock(); locks the BlockList in the hope of preventing other threads from polling the same block out of the BlockList. But that's futile. At this time, the current block self has already been cached in the BlockListIterator in another thread. The call (*block_list).remove(self); removes self from the BlockList.

But when the other thread calls BlockListIterator, it returns the block that has been polled out of the BlockList. BlockListIterator::next() will call cur.load_next_block(), but it will return None because it is already unlinked from the linked list. Then the logical error I mentioned in the previous comment will get the current thread stuck in an infinite loop.

So the fundamental problem is, it is unsafe to iterate through a BlockList while another thread may remove elements from it, even with our current locking attempts.

PR #1106 will not fix this problem because it does not add locking operations to the iterator.

[wks]

BTW, assume there is a block 0x419c0000 (the one I observed). If two threads interleave like this:

1. T1: In Block::attempt_release: call (*block_list).remove(self), where self == 0x419c0000
2. T2: In BlockList::sweep_blocks: call BlockListIterator::next() which returns 0x419c0000, and cache None in the iterator because 0x419c0000 is already unlinked.
3. T2: In BlockList::sweep_blocks: call block.attempt_releaes() where self == 0x419c0000. This is OK because it's safe to call (*block_list).remove(self) but self is already unlinked. BlockList::remove will simply see both prev and next being None.
4. T2: In BlockList::sweep_blocks: call BlockListIterator::next() which returns None and terminates the iteration.
5. T1: In Block::attempt_release: call space.release_block(self) where self == 0x419c0000. It is safe because release_block is idempotent.

When interleaving this way, it will not fall into an infinite loop. But it will cause T2 to iterate fewer blocks than it should, because the BlockList::remove invocation in T1 disrupted the normal iteration process. This can explain why it sweeps fewer blocks in eager sweeping as mentioned in #824

[qinsoon]

Thanks Kunshan. This is quite helpful.

After some thoughts, I think this is what we can do. This logically should be much clearer than what we have right now.

Phase	Allocator local block lists	Global block list	Chunk map	Notes
Allocation	Alloc from local Lazy: sweep local blocks	Move blocks from global to local block lists	-	No change here.
GC - Prepare	-	-	Find used chunks and bzero mark bit	Move the chunk iteration from release to prepare, and do bzero as we iterate through blocks
GC - Trace	Trace object and mark blocks, regardless of block lists	Trace object and mark blocks, regardless of block lists	-	No change here.
GC - Release	Lazy: Move blocks to local unswept list Eager: Sweep local blocks Both: Return local blocks to a temp global list	Lazy: Move blocks to global unswept list Eager: Sweep global blocks	-	Introduce a temp global list. Both lazy and eager sweeping will do their work here on their local/global lists. No race.
GC - End of GC	-	Merge the temp global lists	-	Merge the two global lists. No race.

[wks]

PR #1112 fixed the data race problem in native malloc, and this issue is no longer reproducible. It also added the assertion debug_assert_ne!(cell_size, 0); so that if a similar problem happens again, it will panic instead of hang.