Tests in test_io.rb sometimes read no output

[wks]

Way to reproduce: Checkout the master branch of https://github.com/ruby/ruby and execute the following:

./autogen.sh
mkdir build-debug
cd build-debug
../configure --prefix=$PWD/install --disable-install-doc cppflags="-g3" --with-modular-gc=./gc-modules
make install -j
make modular-gc install-modular-gc MODULAR_GC=mmtk
RUST_LOG=off RUBY_GC_LIBRARY=mmtk make test-all TESTOPTS="--excludes-dir=../test/.excludes-mmtk -v" -j16

And some test cases will fail with the following output:

  1) Failure:
TestIO#test_dup [/home/wks/projects/mmtk-github/parallels/ruby-master/ruby/test/ruby/test_io.rb:1492]:
<"foo\n" + "bar\n"> expected but was
<"">.

  2) Failure:
TestIO#test_close_write [/home/wks/projects/mmtk-github/parallels/ruby-master/ruby/test/ruby/test_io.rb:1842]:
<"foobarbaz"> expected but was
<"">.

  3) Error:
TestEnumerable#test_reverse_each_memory_corruption:
Test::Unit::ProxyError: execution of Test::Unit::CoreAssertions#assert_normal_exit expired timeout (10 sec)
pid 2914630 killed by SIGTERM (signal 15)
| 

    /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/test/ruby/test_enum.rb:903:in 'TestEnumerable#test_reverse_each_memory_corruption'

  4) Error:
TestModule#test_prepend_gc:
Test::Unit::ProxyError: execution of Test::Unit::CoreAssertions#assert_separately expired timeout (10 sec)
pid 2929184 killed by SIGTERM (signal 15)
| 

    /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/test/ruby/test_module.rb:3080:in 'TestModule#test_prepend_gc'

  5) Error:
TestObjectSpace#test_finalizer:
Test::Unit::ProxyError: execution of Test::Unit::CoreAssertions#assert_in_out_err expired timeout (60 sec)
pid 2922050 killed by SIGKILL (signal 9)
| 

    /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/test/ruby/test_objectspace.rb:105:in 'TestObjectSpace#test_finalizer'

  6) Error:
TestWeakKeyMap#test_clear_bug_20691:
Test::Unit::ProxyError: execution of Test::Unit::CoreAssertions#assert_normal_exit expired timeout (10 sec)
pid 2980196 killed by SIGTERM (signal 15)
| 

    /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/test/ruby/test_weakkeymap.rb:65:in 'TestWeakKeyMap#test_clear_bug_20691'

Finished tests in 444.471065s, 64.3911 tests/s, 13663.5126 assertions/s.
28620 tests, 6073036 assertions, 2 failures, 4 errors, 119 skips

ruby -v: ruby 3.5.0dev (2025-04-03T01:14:58Z master b8e2bec914) +PRISM +GC[mmtk] [x86_64-linux]
make: *** [uncommon.mk:953: yes-test-all] Error 6

With -j4 or higher, it will almost guarantee to reproduce one of those failres. And the more threads there are, the higher the chance. They are not reproducible when testing with a single thread (without -j). They are not reproducible when not using the mmtk GC module, or when using the default GC as a GC module.

The first two failures are from test_io.rb. They use popen to launch another ruby process and provide some inputs. In both Failure 1 and Failure 2, it actually read empty string from the output of the sub ruby process.

Other failures expired with timeouts. I am not sure if they are related, so I listed them here, too.

And two stack traces from panics exist during testing. Because tests are executed in parallel, it is unclear which test case caused the panic.

thread '<unnamed>' panicked at src/collection.rs:64:18:
called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }
stack backtrace:
   0: rust_begin_unwind
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:692:5
   1: core::panicking::panic_fmt
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panicking.rs:75:14
   2: core::result::unwrap_failed
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/result.rs:1704:5
   3: core::result::Result<T,E>::unwrap
             at /home/wks/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/result.rs:1109:23
   4: <mmtk_ruby::collection::VMCollection as mmtk::vm::collection::Collection<mmtk_ruby::Ruby>>::spawn_gc_thread
             at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/gc/mmtk/src/collection.rs:40:52
   5: mmtk::scheduler::worker::WorkerGroup<VM>::spawn
             at /home/wks/.cargo/git/checkouts/mmtk-core-e070c0ac3da07192/051bc74/src/scheduler/worker.rs:393:13
   6: mmtk::scheduler::worker::WorkerGroup<VM>::initial_spawn
             at /home/wks/.cargo/git/checkouts/mmtk-core-e070c0ac3da07192/051bc74/src/scheduler/worker.rs:335:9
   7: mmtk::scheduler::scheduler::GCWorkScheduler<VM>::spawn_gc_threads
             at /home/wks/.cargo/git/checkouts/mmtk-core-e070c0ac3da07192/051bc74/src/scheduler/scheduler.rs:93:9
   8: mmtk::mmtk::MMTK<VM>::initialize_collection
             at /home/wks/.cargo/git/checkouts/mmtk-core-e070c0ac3da07192/051bc74/src/mmtk.rs:252:9
   9: mmtk::memory_manager::initialize_collection
             at /home/wks/.cargo/git/checkouts/mmtk-core-e070c0ac3da07192/051bc74/src/memory_manager.rs:496:5
  10: mmtk_initialize_collection
             at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/gc/mmtk/src/api.rs:158:5
  11: rb_gc_impl_ractor_cache_alloc
             at ./gc/mmtk/../../../gc/mmtk/mmtk.c:473:9
  12: rb_gc_ractor_cache_alloc
             at ./../gc.c:2976:12
  13: rb_ractor_main_alloc
             at ./../ractor.c:2074:23
  14: Init_BareVM
             at ./../vm.c:4296:43
  15: ruby_setup
             at ./../eval.c:79:5
  16: ruby_init
             at ./../eval.c:97:17
  17: rb_main
             at ./../main.c:41:5
  18: main
             at ./../main.c:62:12
  19: <unknown>
  20: __libc_start_main
  21: _start
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Ane the other:

thread '<unnamed>' panicked at library/core/src/panicking.rs:218:5:
panic in a function that cannot unwind
stack backtrace:
   0:     0x7c1de895fcba - std::backtrace_rs::backtrace::libunwind::trace::h88deb10bd0145eb8
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5
   1:     0x7c1de895fcba - std::backtrace_rs::backtrace::trace_unsynchronized::he1036f5481c14dff
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x7c1de895fcba - std::sys::backtrace::_print_fmt::hecc345b6e70c4b20
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/sys/backtrace.rs:66:9
   3:     0x7c1de895fcba - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::he089f96442833f67
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/sys/backtrace.rs:39:26
   4:     0x7c1de89af233 - core::fmt::rt::Argument::fmt::h1f77cded99c71a14
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/fmt/rt.rs:177:76
   5:     0x7c1de89af233 - core::fmt::write::h2f210ed4c94745cb
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/fmt/mod.rs:1440:21
   6:     0x7c1de8953fd3 - std::io::Write::write_fmt::h7de08171ab770fb2
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/io/mod.rs:1887:15
   7:     0x7c1de895fb02 - std::sys::backtrace::BacktraceLock::print::h810fbd31421329e6
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/sys/backtrace.rs:42:9
   8:     0x7c1de89621e0 - std::panicking::default_hook::{{closure}}::hbaad47ed9dc6356d
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:295:22
   9:     0x7c1de8961fc0 - std::panicking::default_hook::h24e207139139d40a
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:322:9
  10:     0x7c1de89da0d3 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h9406535c96a49a68
                               at /home/wks/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2007:9
  11:     0x7c1de8ab90d0 - mmtk_ruby::set_panic_hook::{{closure}}::h79df8c0383cf6a55
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/gc/mmtk/src/lib.rs:130:13
  12:     0x7c1de8962a83 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h3af32c23caf5c679
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/alloc/src/boxed.rs:2007:9
  13:     0x7c1de8962a83 - std::panicking::rust_panic_with_hook::ha9131beeb2ddc506
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:836:13
  14:     0x7c1de8962726 - std::panicking::begin_panic_handler::{{closure}}::h1bba0eaeb6da506f
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:694:13
  15:     0x7c1de89601b9 - std::sys::backtrace::__rust_end_short_backtrace::h1d1ca3eade483f4c
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/sys/backtrace.rs:168:18
  16:     0x7c1de89623ed - rust_begin_unwind
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:692:5
  17:     0x7c1de85891dd - core::panicking::panic_nounwind_fmt::runtime::hdd2d1a56a8b6cee7
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panicking.rs:117:22
  18:     0x7c1de85891dd - core::panicking::panic_nounwind_fmt::h0d5ff668f956fac4
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/intrinsics/mod.rs:3869:9
  19:     0x7c1de8589272 - core::panicking::panic_nounwind::h385b7d9bda51382d
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panicking.rs:218:5
  20:     0x7c1de8589436 - core::panicking::panic_cannot_unwind::h757b6ea37bf9b60a
                               at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panicking.rs:307:5
  21:     0x7c1de858cf92 - mmtk_initialize_collection
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/gc/mmtk/src/api.rs:157:1
  22:     0x7c1de858a778 - rb_gc_impl_ractor_cache_alloc
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/gc/mmtk/../../../gc/mmtk/mmtk.c:473:9
  23:     0x61de561f74ae - rb_gc_ractor_cache_alloc
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../gc.c:2976:12
  24:     0x61de56295c6c - rb_ractor_main_alloc
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../ractor.c:2074:23
  25:     0x61de563acf7d - Init_BareVM
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../vm.c:4296:43
  26:     0x61de561cb6cd - ruby_setup
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../eval.c:79:5
  27:     0x61de561cb803 - ruby_init
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../eval.c:97:17
  28:     0x61de561c7e53 - rb_main
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../main.c:41:5
  29:     0x61de561c7ec9 - main
                               at /home/wks/projects/mmtk-github/parallels/ruby-master/ruby/build-debug/../main.c:62:12
  30:     0x7c1de9789488 - <unknown>
  31:     0x7c1de978954c - __libc_start_main
  32:     0x61de561c7d45 - _start
  33:                0x0 - <unknown>
thread caused non-unwinding panic. aborting.

[wks]

If I replace ruby do |f| in test_dup with cat do |f| (where cat invokes the cat program instead of ruby -e '$>.write($<.read)'), the test will pass. The same is true for test_close_write. This means the failures are related to the child processes.

The panic message during execution may be related to the child process. From the stack trace, it looks like it panicked when initializing the MMTk instance.

[wks]

The culprit is this line opts[:rlimit_nproc] = [lim, 2048].min in

  def ruby(*args)
    args = ['-e', '$>.write($<.read)'] if args.empty?
    ruby = EnvUtil.rubybin
    opts = {}
    if defined?(Process::RLIMIT_NPROC)
      lim = Process.getrlimit(Process::RLIMIT_NPROC)[1]
      opts[:rlimit_nproc] = [lim, 2048].min  # HERE!
    end
    f = IO.popen([ruby] + args, 'r+', opts)
    pid = f.pid
    yield(f)
  ensure
    f.close unless !f || f.closed?
    begin
      Process.wait(pid)
    rescue Errno::ECHILD, Errno::ESRCH
    end
  end

In CRuby, IO.popen is implemented as fork then setrlimit then exec. It sets the RLIMIT_NPROC to a maximum of 2048 (while on my laptop running ArchLinux the default value is 126162). Because NPROC also counts threads on Linux, and MMTk spawns many GC worker threads on start-up, the child process run out of thread quota when spawning GC worker threads, and panicked. The panic message Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" } refers to EAGAIN (value 11), and in pthread_create it means "A system-imposed limit on the number of threads was encountered", including RLIMIT_PROC.

Removing opts[:rlimit_nproc] makes both test_dup and test_close_write pass.

The rlimit was introduced in ruby/ruby@b78b66a for no obvious reasons. It was relaxed from 1024 to 2048 in ruby/ruby@0f806b4.

[peterzhu2118]

Shouldn't a limit of 2048 still be more than enough for the test parallelism and number of threads?