Assertion failure in do_work in StopMutators

[wks]

Run the following command on x64, Linux, OpenJDK with GDB

env RUST_BACKTRACE=1 MMTK_MIN_NURSERY=524288 MMTK_MAX_NURSERY=524288 MMTK_PLAN=GenCopy RUST_LOG=info gdb --args /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/build/linux-x86_64-normal-server-slowdebug/jdk/bin/java -XX:+UseThirdPartyHeap -Xms512M -Xmx512M -jar ./dacapo-9.12-MR1-bach.jar lusearch

In GDB, execute the following commands:

handle SIGSEGV noprint nostop
run

and there is a high chance to get an assertion failure:

thread '<unnamed>' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`', /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/gc_work.rs:196:13
stack backtrace:
   0: rust_begin_unwind
             at /rustc/6a758ea7e48416b968955535094479dc2e7cc9e1/library/std/src/panicking.rs:515:5
   1: core::panicking::panic_fmt
             at /rustc/6a758ea7e48416b968955535094479dc2e7cc9e1/library/core/src/panicking.rs:92:14
   2: core::panicking::assert_failed_inner
   3: core::panicking::assert_failed
             at /rustc/6a758ea7e48416b968955535094479dc2e7cc9e1/library/core/src/panicking.rs:117:5
   4: <mmtk::scheduler::gc_work::StopMutators<E> as mmtk::scheduler::work::GCWork<<E as mmtk::scheduler::gc_work::ProcessEdgesWork>::VM>>::do_work
             at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/gc_work.rs:196:13
   5: <W as mmtk::scheduler::work::Work<mmtk::mmtk::MMTK<VM>>>::do_work
             at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/work.rs:34:9
   6: mmtk::scheduler::work::Work::do_work_with_stat
             at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/work.rs:14:9
   7: mmtk::scheduler::scheduler::Scheduler<C>::process_coordinator_work
             at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/scheduler.rs:201:9
   8: mmtk::scheduler::scheduler::Scheduler<C>::wait_for_completion
             at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/scheduler.rs:214:21
   9: mmtk::plan::controller_collector_context::ControllerCollectorContext<VM>::run
             at /home/wks/projects/mmtk-github/mmtk-core/src/plan/controller_collector_context.rs:67:13
  10: mmtk::memory_manager::start_control_collector
             at /home/wks/projects/mmtk-github/mmtk-core/src/memory_manager.rs:36:5
  11: start_control_collector
             at /home/wks/projects/mmtk-github/mmtk-openjdk/mmtk/src/api.rs:54:5
  12: _ZN17MMTkContextThread3runEv
  13: _ZN6Thread8call_runEv
  14: _ZL19thread_native_entryP6Thread
  15: start_thread
  16: __GI___clone

When not using GDB, there is chance that the process will hang for a long time before exiting normally (probably triggering a different bug).

[k-sareen]

I had encountered this earlier (for SemiSpace) and I thought I had fixed it: can you try using SeqCst/AcqRel here to see if that potentially fixes the issue? Release might be too weak.

[wks]

No. I changed the memory order for success to SeqCst, and the same assertion failure can still be reproduced.

I sometimes find that <E::VM as VMBinding>::VMActivePlan::number_of_mutators(); may return a number that is smaller than the actual number of mutators that shall be scanned. For example, in one execution, number_of_mutators() returned 24, but 25 mutators are scanned, that is, scanned_stacks is incremented 25 times.

[k-sareen]

On the flip side, it could be that the there is some issue with the ScanStacks code that makes it scan number_of_mutators() + 1 stacks. I'm not 100% sure where the issue is coming from

[wks]

I printed more logs and found that during the last GC, one GC worker scanned the same mutator twice. Here is a log:

[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW:coord] stop_all_mutators start
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW:coord] stop_all_mutators end
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940011a0] [mutator:0x7ffff00312e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001ef0] [mutator:0x7ffff03bc2e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940011a0] [mutator:0x7ffff00312e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002670] [mutator:0x7ffff08672e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001ef0] [mutator:0x7ffff03bc2e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002750] [mutator:0x7ffff087dae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002670] [mutator:0x7ffff08672e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940023d0] [mutator:0x7ffff087b2e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001ef0] [mutator:0x7ffff03bc2e8] old scanned_stacks = 0, new scanned_stacks = 1
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002750] [mutator:0x7ffff087dae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940023d0] [mutator:0x7ffff087b2e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001490] [mutator:0x7ffff08712e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001df0] [mutator:0x7ffff0878ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940020a0] [mutator:0x7ffff0873ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001620] [mutator:0x7ffff08762e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001490] [mutator:0x7ffff08712e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001df0] [mutator:0x7ffff0878ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940020a0] [mutator:0x7ffff0873ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001620] [mutator:0x7ffff08762e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940026f0] [mutator:0x7ffff086e2e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002750] [mutator:0x7ffff087dae8] old scanned_stacks = 1, new scanned_stacks = 2
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940020a0] [mutator:0x7ffff0873ae8] old scanned_stacks = 3, new scanned_stacks = 4
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940026f0] [mutator:0x7ffff086e2e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001620] [mutator:0x7ffff08762e8] old scanned_stacks = 4, new scanned_stacks = 5
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002670] [mutator:0x7ffff08672e8] old scanned_stacks = 2, new scanned_stacks = 3
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940011a0] [mutator:0x7ffff00312e8] old scanned_stacks = 6, new scanned_stacks = 7
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940026d0] [mutator:0x7ffff08632e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940010f0] [mutator:0x7ffff0434ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001360] [mutator:0x7ffff03c6ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002710] [mutator:0x7ffff086bae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940010f0] [mutator:0x7ffff0434ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002080] [mutator:0x7ffff08652e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001360] [mutator:0x7ffff03c6ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940023d0] [mutator:0x7ffff087b2e8] old scanned_stacks = 7, new scanned_stacks = 8
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001490] [mutator:0x7ffff08712e8] old scanned_stacks = 5, new scanned_stacks = 6
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002080] [mutator:0x7ffff08652e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940026d0] [mutator:0x7ffff08632e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001360] [mutator:0x7ffff03c6ae8] old scanned_stacks = 9, new scanned_stacks = 10
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002450] [mutator:0x7ffff03c42e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940024b0] [mutator:0x7ffff03c1ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002710] [mutator:0x7ffff086bae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940025f0] [mutator:0x7ffff03beae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001df0] [mutator:0x7ffff0878ae8] old scanned_stacks = 8, new scanned_stacks = 9
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940018b0] [mutator:0x7ffff039cae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940025f0] [mutator:0x7ffff03beae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002450] [mutator:0x7ffff03c42e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940024b0] [mutator:0x7ffff03c1ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002570] [mutator:0x7ffff0379ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940018b0] [mutator:0x7ffff039cae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002450] [mutator:0x7ffff03c42e8] old scanned_stacks = 10, new scanned_stacks = 11
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001e10] [mutator:0x7ffff0869ae8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002570] [mutator:0x7ffff0379ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940024b0] [mutator:0x7ffff03c1ae8] old scanned_stacks = 11, new scanned_stacks = 12
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fffd00011b0] [mutator:0x7ffff086e2e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940018b0] [mutator:0x7ffff039cae8] old scanned_stacks = 12, new scanned_stacks = 13
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001e10] [mutator:0x7ffff0869ae8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002630] [mutator:0x7ffff03772e8] ScanStackRoot begin
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fffd00011b0] [mutator:0x7ffff086e2e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940025f0] [mutator:0x7ffff03beae8] old scanned_stacks = 13, new scanned_stacks = 14
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002630] [mutator:0x7ffff03772e8] I see mutaturs = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940010f0] [mutator:0x7ffff0434ae8] old scanned_stacks = 14, new scanned_stacks = 15
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002570] [mutator:0x7ffff0379ae8] old scanned_stacks = 15, new scanned_stacks = 16
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002630] [mutator:0x7ffff03772e8] old scanned_stacks = 16, new scanned_stacks = 17
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002710] [mutator:0x7ffff086bae8] old scanned_stacks = 17, new scanned_stacks = 18
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940026f0] [mutator:0x7ffff086e2e8] old scanned_stacks = 18, new scanned_stacks = 19
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94002080] [mutator:0x7ffff08652e8] old scanned_stacks = 19, new scanned_stacks = 20
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff940026d0] [mutator:0x7ffff08632e8] old scanned_stacks = 20, new scanned_stacks = 21
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001e10] [mutator:0x7ffff0869ae8] old scanned_stacks = 21, new scanned_stacks = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001e10] [mutator:0x7ffff0869ae8] current = 22, mutators = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001e10] [mutator:0x7ffff0869ae8] attempt to cmpxchg 22 to 0
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fff94001e10] [mutator:0x7ffff0869ae8] cmpxchg successful old scanned_stacks = 22, new scanned_stacks = 0, number_of_mutators = 22
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] [STW] [worker:0x7fffd00011b0] [mutator:0x7ffff086e2e8] old scanned_stacks = 0, new scanned_stacks = 1
[2021-07-19T03:56:12Z INFO  mmtk::scheduler::gc_work] End of GC

Note that mutator 0x7ffff086e2e8 is processed by two different workers, namely 0x7fffd00011b0 and 0x7fff940026f0.

[k-sareen]

Okay so seems like I was right -- for some reason we scan number_of_mutators() + 1 times. I can't say I'm too familiar with the root scanning code, but is this perchance an OpenJDK binding bug wherein we accidentally make an extra ScanStackRoot work packet?

[wks]

So I added a log to openjdk/mmtk/src/collections.rs:create_mutator_scan_work. You are right. When that bug occurs, this function is called twice for a mutator. More interestingly, that mutator is always the first mutator passed to create_mutator_scan_work in one STW.

[k-sareen]

Hmm -- yep that was the function I was looking at as well. Other than stop_all_mutators() I can't see where the create_mutator_scan_work() function is used. Seems like a potential race condition in the binding then?

[k-sareen]

Seems like create_stack_scan_work() can be called by report_java_thread_yield() in openjdk/mmtkHeap.cpp:503 as a function pointer to it is passed around. The report_java_thread_yield() function seems to be used in the safepoint code for our OpenJDK fork at src/hotspot/share/runtime/safepoint.cpp:297.

Edit: Perhaps @wenyuzhao can comment on this discussion. I think he primarily worked on the OpenJDK binding.

[wks]

I found SafepointSynchronize::begin() called twice after one stop_all_mutators() call.

Edit: I confirmed that one thread is the "MMTk Controller" thread which called stop_all_mutators(). The other thread is a "VM Thread".

Edit2: I have pin-pointed the two racing threads by letting both threads abort() inside the function SafepointSynchronize::begin() if one entered that function before the other returns from that function. Their stack traces are:

Thread 3: The VM Thread

(gdb) t 3
[Switching to thread 3 (Thread 0x7ffff4a22640 (LWP 167165))]
#0  0x00007ffff7d9ed22 in raise () from /usr/lib/libc.so.6
(gdb) bt
#0  0x00007ffff7d9ed22 in raise () from /usr/lib/libc.so.6
mmtk/mmtk-core#1  0x00007ffff7d88862 in abort () from /usr/lib/libc.so.6
mmtk/mmtk-core#2  0x00007ffff6e90504 in SafepointSynchronize::begin () at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/runtime/safepoint.cpp:516
mmtk/mmtk-core#3  0x00007ffff707e503 in VMThread::loop (this=0x7ffff0360800) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/runtime/vmThread.cpp:542
mmtk/mmtk-core#4  0x00007ffff707d9a3 in VMThread::run (this=0x7ffff0360800) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/runtime/vmThread.cpp:310
mmtk/mmtk-core#5  0x00007ffff6f97ddc in Thread::call_run (this=0x7ffff0360800) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/runtime/thread.cpp:385
mmtk/mmtk-core#6  0x00007ffff6d943d5 in thread_native_entry (thread=0x7ffff0360800) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/os/linux/os_linux.cpp:787
mmtk/mmtk-core#7  0x00007ffff7f55259 in start_thread () from /usr/lib/libpthread.so.0
mmtk/mmtk-core#8  0x00007ffff7e605e3 in clone () from /usr/lib/libc.so.6

Thread 19: The MMTk Coordinator thread

(gdb) t 19
[Switching to thread 19 (Thread 0x7fffd43e5640 (LWP 167181))]
#0  0x00007ffff7d9ed22 in raise () from /usr/lib/libc.so.6
(gdb) bt
#0  0x00007ffff7d9ed22 in raise () from /usr/lib/libc.so.6
mmtk/mmtk-core#1  0x00007ffff7d88862 in abort () from /usr/lib/libc.so.6
mmtk/mmtk-core#2  0x00007ffff6e8f6af in SafepointSynchronize::begin () at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/runtime/safepoint.cpp:163
mmtk/mmtk-core#3  0x00007ffff6cffadc in mmtk_stop_all_mutators (tls=0x7ffff03ba000, 
    create_stack_scan_work=0x7ffff58faa30 <mmtk_openjdk::collection::create_mutator_scan_work<mmtk::plan::gencopy::gc_work::GenCopyNurseryProcessEdges<mmtk_openjdk::OpenJDK>>>)
    at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/../../openjdk/mmtkUpcalls.cpp:53
mmtk/mmtk-core#4  0x00007ffff58fadc5 in mmtk_openjdk::collection::{{impl}}::stop_all_mutators<mmtk::plan::gencopy::gc_work::GenCopyNurseryProcessEdges<mmtk_openjdk::OpenJDK>> (tls=...)
    at src/collection.rs:33
mmtk/mmtk-core#5  0x00007ffff590a44e in mmtk::scheduler::gc_work::{{impl}}::do_work<mmtk::plan::gencopy::gc_work::GenCopyNurseryProcessEdges<mmtk_openjdk::OpenJDK>> (self=0x1, 
    worker=0x7ffff00324d8, mmtk=0x7ffff5ce3010 <<mmtk_openjdk::SINGLETON as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/gc_work.rs:197
mmtk/mmtk-core#6  0x00007ffff5915a8b in mmtk::scheduler::work::{{impl}}::do_work<mmtk_openjdk::OpenJDK,mmtk::scheduler::gc_work::StopMutators<mmtk::plan::gencopy::gc_work::GenCopyNurseryProcessEdges<mmtk_openjdk::OpenJDK>>> (self=0x1, worker=0x7ffff00324d8, mmtk=0x7ffff5ce3010 <<mmtk_openjdk::SINGLETON as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/work.rs:34
mmtk/mmtk-core#7  mmtk::scheduler::work::Work::do_work_with_stat<mmtk::scheduler::gc_work::StopMutators<mmtk::plan::gencopy::gc_work::GenCopyNurseryProcessEdges<mmtk_openjdk::OpenJDK>>,mmtk::mmtk::MMTK<mmtk_openjdk::OpenJDK>> (self=0x1, worker=0x7ffff00324d8, context=0x7ffff5ce3010 <<mmtk_openjdk::SINGLETON as core::ops::deref::Deref>::deref::__stability::LAZY>)
    at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/work.rs:14
mmtk/mmtk-core#8  0x00007ffff5940d13 in mmtk::scheduler::scheduler::Scheduler<mmtk::mmtk::MMTK<mmtk_openjdk::OpenJDK>>::process_coordinator_work<mmtk::mmtk::MMTK<mmtk_openjdk::OpenJDK>> (
    self=0x7ffff00322b0, work=...) at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/scheduler.rs:201
mmtk/mmtk-core#9  0x00007ffff59401e7 in mmtk::scheduler::scheduler::Scheduler<mmtk::mmtk::MMTK<mmtk_openjdk::OpenJDK>>::wait_for_completion<mmtk::mmtk::MMTK<mmtk_openjdk::OpenJDK>> (
    self=0x7ffff00322b0) at /home/wks/projects/mmtk-github/mmtk-core/src/scheduler/scheduler.rs:214
mmtk/mmtk-core#10 0x00007ffff58a5c5e in mmtk::plan::controller_collector_context::ControllerCollectorContext<mmtk_openjdk::OpenJDK>::run<mmtk_openjdk::OpenJDK> (self=0x7ffff024ae28, tls=...)
    at /home/wks/projects/mmtk-github/mmtk-core/src/plan/controller_collector_context.rs:67
mmtk/mmtk-core#11 0x00007ffff587d4f8 in mmtk::memory_manager::start_control_collector<mmtk_openjdk::OpenJDK> (
    mmtk=0x7ffff5ce3010 <<mmtk_openjdk::SINGLETON as core::ops::deref::Deref>::deref::__stability::LAZY>, tls=...)
    at /home/wks/projects/mmtk-github/mmtk-core/src/memory_manager.rs:36
mmtk/mmtk-core#12 0x00007ffff58ff22c in mmtk_openjdk::api::start_control_collector (tls=...) at src/api.rs:54
mmtk/mmtk-core#13 0x00007ffff6cfbe94 in MMTkContextThread::run (this=0x7ffff03ba000) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/../../openjdk/mmtkContextThread.cpp:34
mmtk/mmtk-core#14 0x00007ffff6f97ddc in Thread::call_run (this=0x7ffff03ba000) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/runtime/thread.cpp:385
mmtk/mmtk-core#15 0x00007ffff6d943d5 in thread_native_entry (thread=0x7ffff03ba000) at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/os/linux/os_linux.cpp:787
mmtk/mmtk-core#16 0x00007ffff7f55259 in start_thread () from /usr/lib/libpthread.so.0
mmtk/mmtk-core#17 0x00007ffff7e605e3 in clone () from /usr/lib/libc.so.6

Edit3: Here are the log messages and the list of threads:

Log:

[2021-07-19T10:40:14Z INFO  mmtk::plan::global]   [POLL] nursery: Triggering collection
[2021-07-19T10:40:14Z INFO  mmtk::plan::global]   [POLL] nursery: Triggering collection
[OpenJDK] [tid=167165] void SafepointSynchronize::begin() called.
[OpenJDK] [tid=167165] while(still_running) nof_threads = 23, still_running = 23
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff0031000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff0031000, mutator: 0x7ffff00312e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff0377000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff0377000, mutator: 0x7ffff03772e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff0379800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff0379800, mutator: 0x7ffff0379ae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff039c800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff039c800, mutator: 0x7ffff039cae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff03bc000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff03bc000, mutator: 0x7ffff03bc2e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff03be800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff03be800, mutator: 0x7ffff03beae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff03c1800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff03c1800, mutator: 0x7ffff03c1ae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff03c4000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff03c4000, mutator: 0x7ffff03c42e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff03c6800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff03c6800, mutator: 0x7ffff03c6ae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff043c800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff043c800, mutator: 0x7ffff043cae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7fff7832b000
[OpenJDK] Reporting Java thread yield... cur = 0x7fff7832b000, mutator: 0x7fff7832b2e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08ac000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08ac000, mutator: 0x7ffff08ac2e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08ad000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08ad000, mutator: 0x7ffff08ad2e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08af000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08af000, mutator: 0x7ffff08af2e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08b1800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08b1800, mutator: 0x7ffff08b1ae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08b3800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08b3800, mutator: 0x7ffff08b3ae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08b6000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08b6000, mutator: 0x7ffff08b62e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08b8000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08b8000, mutator: 0x7ffff08b82e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08ba800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08ba800, mutator: 0x7ffff08baae8
[2021-07-19T10:40:14Z INFO  mmtk::scheduler::gc_work] [STW:coord] stop_all_mutators start
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08bc800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08bc800, mutator: 0x7ffff08bcae8
[OpenJDK] [tid=167181] void SafepointSynchronize::begin() called.
[OpenJDK] [tid=167181] Oh, no! Thread 167165 has already entered SafepointSynchronize::begin()
[2021-07-19T10:40:14Z INFO  mmtk_openjdk::collection] [OpenJDK binding] Creating mutator scan work... mutator = 0x7ffff08bcae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08bf000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08bf000, mutator: 0x7ffff08bf2e8
[2021-07-19T10:40:14Z INFO  mmtk_openjdk::collection] [OpenJDK binding] Creating mutator scan work... mutator = 0x7ffff08bf2e8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08c1800
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08c1800, mutator: 0x7ffff08c1ae8
[2021-07-19T10:40:14Z INFO  mmtk_openjdk::collection] [OpenJDK binding] Creating mutator scan work... mutator = 0x7ffff08c1ae8
[OpenJDK] [tid=167165]   calling report_java_thread_yield 0x7ffff08c4000
[OpenJDK] Reporting Java thread yield... cur = 0x7ffff08c4000, mutator: 0x7ffff08c42e8
[2021-07-19T10:40:14Z INFO  mmtk_openjdk::collection] [OpenJDK binding] Creating mutator scan work... mutator = 0x7ffff08c42e8
[OpenJDK] [tid=167165] end of while. nof_threads = 23, still_running = 0
[OpenJDK] [tid=167165] Ouch! Thread 167181 entered SafepointSynchronize::begin() before I exit!

Threads:

(gdb) info threads
  Id   Target Id                                            Frame 
  1    Thread 0x7ffff7d61380 (LWP 167133) "java"            0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  2    Thread 0x7ffff56ba640 (LWP 167164) "java"            0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  3    Thread 0x7ffff4a22640 (LWP 167165) "VM Thread"       0x00007ffff7d9ed22 in raise () from /usr/lib/libc.so.6
  4    Thread 0x7ffff4920640 (LWP 167166) "Reference Handl" 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  5    Thread 0x7ffff481f640 (LWP 167167) "Finalizer"       0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  6    Thread 0x7ffff4135640 (LWP 167168) "MMTk Finalizer " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  7    Thread 0x7fffd4ffd640 (LWP 167169) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  8    Thread 0x7fffd4efb640 (LWP 167170) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  9    Thread 0x7fffd4df9640 (LWP 167171) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  10   Thread 0x7fffd4cf7640 (LWP 167172) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  11   Thread 0x7fffd4bf5640 (LWP 167173) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  12   Thread 0x7fffd4af3640 (LWP 167174) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  13   Thread 0x7fffd49f1640 (LWP 167175) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  14   Thread 0x7fffd48ef640 (LWP 167176) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  15   Thread 0x7fffd47ed640 (LWP 167177) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  16   Thread 0x7fffd46eb640 (LWP 167178) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  17   Thread 0x7fffd45e9640 (LWP 167179) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  18   Thread 0x7fffd44e7640 (LWP 167180) "MMTk Collector " 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
* 19   Thread 0x7fffd43e5640 (LWP 167181) "MMTk Controller" 0x00007ffff7d9ed22 in raise () from /usr/lib/libc.so.6
  20   Thread 0x7fffd42e3640 (LWP 167182) "Signal Dispatch" 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  21   Thread 0x7fffd41e2640 (LWP 167183) "Service Thread"  0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  22   Thread 0x7fff87fff640 (LWP 167184) "C2 CompilerThre" 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  23   Thread 0x7fff87efe640 (LWP 167185) "C1 CompilerThre" 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  24   Thread 0x7fff87dfd640 (LWP 167186) "Sweeper thread"  0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  25   Thread 0x7fff87cfc640 (LWP 167187) "Common-Cleaner"  0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  28   Thread 0x7fff879f9640 (LWP 167193) "VM Periodic Tas" 0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  29   Thread 0x7fff87bfb640 (LWP 167200) "C2 CompilerThre" 0x00007ffff643b70e in GrowableArray<unsigned int>::at (this=0x7fff87bf7220, i=0)
    at /home/wks/projects/mmtk-github/mmtk-openjdk/repos/openjdk/src/hotspot/share/utilities/growableArray.hpp:248
  30   Thread 0x7fff87afa640 (LWP 167201) "Query0"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  31   Thread 0x7fff878f7640 (LWP 167202) "Query1"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  32   Thread 0x7fff877f6640 (LWP 167203) "Query2"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  33   Thread 0x7fff876f5640 (LWP 167204) "Query3"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  34   Thread 0x7fff875f4640 (LWP 167205) "Query4"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  35   Thread 0x7fff874f3640 (LWP 167206) "Query5"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  36   Thread 0x7fff873f2640 (LWP 167207) "Query6"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  37   Thread 0x7fff872f1640 (LWP 167208) "Query7"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  38   Thread 0x7fff871f0640 (LWP 167209) "Query8"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  39   Thread 0x7fff870ef640 (LWP 167210) "Query9"          0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  40   Thread 0x7fff86fee640 (LWP 167211) "Query10"         0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0
  41   Thread 0x7fff86eed640 (LWP 167212) "Query11"         0x00007ffff7f618ca in __futex_abstimed_wait_common64 () from /usr/lib/libpthread.so.0

[k-sareen]

Aha. So it is related to the report_java_thread_yield(). Should we add a guard somewhere? As a hack, we could keep track of the first mutator reference in create_mutator_scan_work() and only create the ScanStackRoot work packet if it's not equal to the first mutator. We then reset the mutator reference in mmtk_resume_mutators() in openjdk/mmtkUpcalls.cpp:56.

[wks]

@k-sareen I later found (see my previous post) that it is not just the first mutator that is added twice, but other mutators are, too. As we found that the root cause is the race between two threads (the VM Thread and the MMTk Coordinator thread). I already encountered cases where all mutator threads are visited by both the VM Thread and the MMTk Coordinator thread before mmtk-core starts scanning any stack.

I grepped the vanilla OpenJDK code, and found that the SafepointSynchronize::begin() function is only ever called by the "VM Thread" (I mean there is a thread in OpenJDK named "VM Thread"). So we need to figure out whether it is legal at all to call SafepointSynchronize::begin() from other threads. One obvious way is to look at how existing STW GC algorithms in OpenJDK stop the world.

[k-sareen]

Maybe we should migrate this bug to mmtk-openjdk?

[wks]

@k-sareen From what I found out yesterday, yes. It is a bug of the OpenJDK binding.

[wks]

The "VM Thread" does various VM operations which require global stop-the-world. From the log, I observed the VM thread doing "RevokeBias" and "Deoptimize" when racing with MMTk Coordinator.