Binaryen: ThreadPool asserting while running tests in parallel

Created on 19 Jan 2018 · 25Comments · Source: WebAssembly/binaryen

After I've upgraded binaryen from 9f4e32 to the latest master in https://github.com/pepyakin/binaryen-rs I started to get assertion errors while running tests, like:

binaryen-bdb9684fb6e3b36a: /home/travis/build/pepyakin/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp:50: wasm::Thread::Thread(): Assertion `!ThreadPool::get()→isRunning()' failed.

When I run these tests in single-thread mode the error don't show up.

I'm using binaryen-c API.

Source

pepyakin

All 25 comments

Hmm, I wonder if there is some difference in startup between C++ and Rust that could cause that? Not sure what it could be, though.

What test is it running where that fails?
Is it possible to get a full stack trace for that assert?
Building with BINARYEN_THREAD_DEBUG (just src/support/threads.cpp needs it) will produce runtime logging that could also help here.
If it's feasible to bisect to find the bad commit, that could help too (looks like the range is from last september til today).

kripken on 19 Jan 2018

It seems there are actually different failures that show up non-deterministically!

Assertion failed: (doWorkers.size() == num), function work, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 161.

Assertion failed: (old == threads.size()), function resetThreadsAreReady, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 195.

Assertion failed: (!running), function work, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 162.

Assertion failed: (ec == 0), function unlock, file /BuildRoot/Library/Caches/com.apple.xbs/Sources/libcxx/libcxx-307.5/src/mutex.cpp, line 48.

And it also can just succeed or never terminate!

pepyakin on 19 Jan 2018

So, when it doesn't terminate, there are couple of threads sitting in wasm::Thread::mainLoop:98

pepyakin on 19 Jan 2018

https://github.com/pepyakin/binaryen-rs/blob/d307d5ae20918effb6f273f80671a0376a0165f4/src/lib.rs#L1236

Also, the same failure was spotted while executing this test
https://github.com/pepyakin/binaryen-rs/blob/d307d5ae20918effb6f273f80671a0376a0165f4/src/lib.rs#L1252

Assertion failed: (ec == 0), function unlock, file /BuildRoot/Library/Caches/com.apple.xbs/Sources/libcxx/libcxx-307.5/src/mutex.cpp, line 48.
Process 98665 stopped
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-34bc79fc7b73fca8) stopped.
(lldb) bt
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x00007fff8ece7142 libc++.1.dylib`std::__1::mutex::unlock() + 54
    frame #5: 0x0000000100389292 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::initialize(unsigned long) [inlined] std::__1::unique_lock<std::__1::mutex>::~unique_lock(this=0x000070000679bd20) at __mutex_base:157
    frame #6: 0x0000000100389272 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::initialize(unsigned long) [inlined] std::__1::unique_lock<std::__1::mutex>::~unique_lock(this=0x000070000679bd20) at __mutex_base:155
    frame #7: 0x0000000100389272 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::initialize(this=0x0000000100c021e0, num=8) at threads.cpp:126
    frame #8: 0x0000000100387a14 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::get() at threads.cpp:143
    frame #9: 0x00000001000e8477 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000679c970)::$_0::operator()() const at pass.cpp:276
    frame #10: 0x00000001000e6dd3 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000679d550) at pass.cpp:311
    frame #11: 0x000000010040a969 binaryen-34bc79fc7b73fca8`wasm::WasmValidator::validate(this=0x000070000679d758, module=0x0000000100c02730, features=1, flags=2) at wasm-validator.cpp:1029
    frame #12: 0x00000001000469e4 binaryen-34bc79fc7b73fca8`::BinaryenModuleValidate(module=0x0000000100c02730) at binaryen-c.cpp:2004
    frame #13: 0x0000000100006ee9 binaryen-34bc79fc7b73fca8`binaryen::Module::is_valid::h6f7fe82e8fe3f983 + 57
    frame #14: 0x000000010000b512 binaryen-34bc79fc7b73fca8`binaryen::tests::test_hello_world::hcd6bc71bba10d3ff + 450
    frame #15: 0x000000010002c542 binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #16: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #17: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #18: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #19: 0x000000010001ca41 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #20: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #21: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #22: 0x000000010001c8a9 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #23: 0x00000001000222d8 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #24: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #25: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #26: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #27: 0x0000000100038a02 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #28: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #29: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #30: 0x000000010003897c binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #31: 0x0000000100461908 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #32: 0x0000000100461905 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #33: 0x000000010046b9c9 binaryen-34bc79fc7b73fca8`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #34: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #35: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #36: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

pepyakin on 19 Jan 2018

https://github.com/pepyakin/binaryen-rs/blob/d307d5ae20918effb6f273f80671a0376a0165f4/src/lib.rs#L1236

Assertion failed: (!running), function work, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 162.
Process 98697 stopped
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-34bc79fc7b73fca8) stopped.
(lldb) bt
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x00000001003899be binaryen-34bc79fc7b73fca8`wasm::ThreadPool::work(this=0x00000001025003c0, doWorkers=size=1)>, std::__1::allocator<std::__1::function<wasm::ThreadWorkState ()> > >&) at threads.cpp:162
    frame #5: 0x00000001000e8931 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000ef42970)::$_0::operator()() const at pass.cpp:299
    frame #6: 0x00000001000e6dd3 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000ef43550) at pass.cpp:311
    frame #7: 0x000000010040a969 binaryen-34bc79fc7b73fca8`wasm::WasmValidator::validate(this=0x000070000ef43758, module=0x0000000100c09c50, features=1, flags=2) at wasm-validator.cpp:1029
    frame #8: 0x00000001000469e4 binaryen-34bc79fc7b73fca8`::BinaryenModuleValidate(module=0x0000000100c09c50) at binaryen-c.cpp:2004
    frame #9: 0x0000000100006ee9 binaryen-34bc79fc7b73fca8`binaryen::Module::is_valid::h6f7fe82e8fe3f983 + 57
    frame #10: 0x000000010000b512 binaryen-34bc79fc7b73fca8`binaryen::tests::test_hello_world::hcd6bc71bba10d3ff + 450
    frame #11: 0x000000010002c542 binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #12: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #13: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #14: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #15: 0x000000010001ca41 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #16: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #17: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #18: 0x000000010001c8a9 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #19: 0x00000001000222d8 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #20: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #21: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #22: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #23: 0x0000000100038a02 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #24: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #25: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #26: 0x000000010003897c binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #27: 0x0000000100461908 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #28: 0x0000000100461905 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #29: 0x000000010046b9c9 binaryen-34bc79fc7b73fca8`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #30: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #31: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #32: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

pepyakin on 19 Jan 2018

https://github.com/pepyakin/binaryen-rs/blob/d307d5ae20918effb6f273f80671a0376a0165f4/src/lib.rs#L1252

Assertion failed: (!ThreadPool::get()->isRunning()), function Thread, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 50.
test tests::test_relooper_with_different_module ... ok
Process 98716 stopped
* thread #2, name = 'tests::test_simple', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-34bc79fc7b73fca8) stopped.
(lldb) bt
* thread #2, name = 'tests::test_simple', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x00000001003872f3 binaryen-34bc79fc7b73fca8`wasm::Thread::Thread(this=0x0000000100c025e0) at threads.cpp:50
    frame #5: 0x0000000100387ef5 binaryen-34bc79fc7b73fca8`wasm::Thread::Thread(this=0x0000000100c025e0) at threads.cpp:49
    frame #6: 0x0000000100389444 binaryen-34bc79fc7b73fca8`std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > wasm::make_unique<wasm::Thread>() at utilities.h:60
    frame #7: 0x0000000100388882 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::initialize(this=0x0000000100c02390, num=8) at threads.cpp:115
    frame #8: 0x0000000100387a14 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::get() at threads.cpp:143
    frame #9: 0x00000001000e8477 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000a1c78f0)::$_0::operator()() const at pass.cpp:276
    frame #10: 0x00000001000e6dd3 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000a1c84d0) at pass.cpp:311
    frame #11: 0x000000010040a969 binaryen-34bc79fc7b73fca8`wasm::WasmValidator::validate(this=0x000070000a1c86d8, module=0x0000000102500180, features=1, flags=2) at wasm-validator.cpp:1029
    frame #12: 0x00000001000469e4 binaryen-34bc79fc7b73fca8`::BinaryenModuleValidate(module=0x0000000102500180) at binaryen-c.cpp:2004
    frame #13: 0x0000000100006ee9 binaryen-34bc79fc7b73fca8`binaryen::Module::is_valid::h6f7fe82e8fe3f983 + 57
    frame #14: 0x000000010000b809 binaryen-34bc79fc7b73fca8`binaryen::tests::test_simple::h103cd8ffdd599a23 + 617
    frame #15: 0x000000010002c542 binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #16: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #17: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #18: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #19: 0x000000010001ca41 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #20: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #21: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #22: 0x000000010001c8a9 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #23: 0x00000001000222d8 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #24: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #25: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #26: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #27: 0x0000000100038a02 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #28: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #29: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #30: 0x000000010003897c binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #31: 0x0000000100461908 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #32: 0x0000000100461905 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #33: 0x000000010046b9c9 binaryen-34bc79fc7b73fca8`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #34: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #35: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #36: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13
(lldb)

Third one from BinaryenModuleValidate

pepyakin on 19 Jan 2018

https://github.com/pepyakin/binaryen-rs/blob/d307d5ae20918effb6f273f80671a0376a0165f4/src/lib.rs#L1236

Another one from BinaryenModuleValidate

Assertion failed: (!ThreadPool::test to_cstr::tests::test_use_cases ... get()->isRunning()), function Thread, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 50.
ok
Process 98751 stopped
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-34bc79fc7b73fca8) stopped.
(lldb) bt
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x00000001003872f3 binaryen-34bc79fc7b73fca8`wasm::Thread::Thread(this=0x0000000102b00c00) at threads.cpp:50
    frame #5: 0x0000000100387ef5 binaryen-34bc79fc7b73fca8`wasm::Thread::Thread(this=0x0000000102b00c00) at threads.cpp:49
    frame #6: 0x0000000100389444 binaryen-34bc79fc7b73fca8`std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > wasm::make_unique<wasm::Thread>() at utilities.h:60
    frame #7: 0x0000000100388882 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::initialize(this=0x0000000100e003a0, num=8) at threads.cpp:115
    frame #8: 0x0000000100387a14 binaryen-34bc79fc7b73fca8`wasm::ThreadPool::get() at threads.cpp:143
    frame #9: 0x00000001000e8477 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000b31e970)::$_0::operator()() const at pass.cpp:276
    frame #10: 0x00000001000e6dd3 binaryen-34bc79fc7b73fca8`wasm::PassRunner::run(this=0x000070000b31f550) at pass.cpp:311
    frame #11: 0x000000010040a969 binaryen-34bc79fc7b73fca8`wasm::WasmValidator::validate(this=0x000070000b31f758, module=0x0000000100d004a0, features=1, flags=2) at wasm-validator.cpp:1029
    frame #12: 0x00000001000469e4 binaryen-34bc79fc7b73fca8`::BinaryenModuleValidate(module=0x0000000100d004a0) at binaryen-c.cpp:2004
    frame #13: 0x0000000100006ee9 binaryen-34bc79fc7b73fca8`binaryen::Module::is_valid::h6f7fe82e8fe3f983 + 57
    frame #14: 0x000000010000b512 binaryen-34bc79fc7b73fca8`binaryen::tests::test_hello_world::hcd6bc71bba10d3ff + 450
    frame #15: 0x000000010002c542 binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #16: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #17: 0x000000010002c53d binaryen-34bc79fc7b73fca8`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #18: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #19: 0x000000010001ca41 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #20: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #21: 0x000000010001c9fc binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #22: 0x000000010001c8a9 binaryen-34bc79fc7b73fca8`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #23: 0x00000001000222d8 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #24: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #25: 0x00000001000222c2 binaryen-34bc79fc7b73fca8`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #26: 0x0000000100479aef binaryen-34bc79fc7b73fca8`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #27: 0x0000000100038a02 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #28: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #29: 0x00000001000389c9 binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #30: 0x000000010003897c binaryen-34bc79fc7b73fca8`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #31: 0x0000000100461908 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #32: 0x0000000100461905 binaryen-34bc79fc7b73fca8`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #33: 0x000000010046b9c9 binaryen-34bc79fc7b73fca8`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #34: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #35: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #36: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

pepyakin on 19 Jan 2018

I have a poor understanding of Rust stack traces, but it looks like

Rust starts to panic
During panicking it starts to run a binaryen test
The binaryen test tries to do stuff with threads but hits an assert

Is it possible Rust panicking leaves things in a state where mallocs or other system operations will fail?

kripken on 19 Jan 2018

I don't know about C++ memory model and concurrency semantics but doesn't this should be wrapped in somekind of mutex?

https://github.com/WebAssembly/binaryen/blob/63ebdb6d360c6e96e6f0e10974dfd8c29baade73/src/support/threads.cpp#L140-L146

Because, at the time we get into initialze some other thread might get there and initialize pool twice?

Rust starts to panic

No there are no panics. What you see is machinery to catch a panic and a test setup.

pepyakin on 19 Jan 2018

Example of BINARYEN_THREAD_DEBUG

[POOL] initialize()
[POOL] initialize()
[POOL] work() sequentially
[POOL] reset threads are ready
test to_cstr::tests::test_use_cases ... ok
test tests::test_relooper_with_different_module ... ok
(block
[THREAD  (block 0x70000c3a1000$] block$2$breakchecking for work

  [THREAD 0x70000bd98000(] nopchecking for work
)
  ([THREAD block0x70000be1b000]
checking for work
   (br $block$2$break)
  )
 )
 (block
  (nop[THREAD )0x70000be9e000
]  checking for work
)
)
[THREAD 0x70000c424000] checking for work
test relooper::tests::test ... [POOL] notify thread is ready
ok
[THREAD 0x70000c4a7000] checking for work
[THREAD 0x70000c52a000] checking for work
[POOL] initialize() waiting
[THREAD 0x70000c5ad000] checking for work
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] work() on threads
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] are threads ready?
[POOL] notify thread is ready
[POOL] reset threads are ready
Assertion failed: (!ThreadPool::get()->isRunning()), function Thread, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 52.
error: An unknown error occurred

running 8 tests
test to_cstr::tests::test_to_cstr_stash_option ... ok
test tests::test_use_same_expr_twice ... ok
test to_cstr::tests::test_use_cases ... [POOL] ok
initialize()
[POOL] work() sequentially
[POOL] work() sequentially
[POOL] reset threads are ready
test tests::test_relooper_with_different_module ... [THREAD ok
0x70001060e000] checking for work
([THREAD test tests::test_unreachable ... ok
block
0x700010005000] checking for work
 (block [THREAD $block$2$break
0x700010088000  (nop)
 ]  checking for work
(block
[POOL] notify thread is ready
   (br $block$2$break)
  )
 )
[THREAD  0x70001010b000(block
]  checking for work
 (nop)
[THREAD  )
0x700010691000)]
checking for work
[THREAD 0x700010714000] test relooper::tests::test ... checking for work
ok
[THREAD 0x700010797000] checking for work
[POOL] initialize() waiting
[POOL] notify thread is ready
[THREAD 0x70001040b000] checking for work
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] work() on threads
[POOL] notify thread is ready
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x70001060e000] thread waiting
[THREAD 0x700010005000] thread waiting
[THREAD 0x700010088000] thread waiting
[THREAD 0x700010691000] thread waiting
[THREAD 0x70001010b000] thread waiting
[THREAD 0x700010714000] thread waiting
[POOL] reset threads are ready
Assertion failed: (old == threads.size()), function resetThreadsAreReady, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 197.

pepyakin on 19 Jan 2018

No there are no panics. What you see is machinery to catch a panic and a test setup.

I see, thanks. As I said, I know very little about Rust :)

I don't know about C++ memory model and concurrency semantics but doesn't this should be wrapped in somekind of mutex?

Hmm, good point. The intention was that that should be safe, as the threadpool is only requested from the main thread. However, I see we added asserts in the thread constructors, which get the pool to check if it's running, which run in their own threads ;) lol

Another issue is that I think you are running tests in multiple threads? We didn't test that, so we need some more carefulness to handle that properly.

Fixes for both should be in #1377

kripken on 19 Jan 2018

I see, thanks. As I said, I know very little about Rust :)

Yeah, feel free to ask in future!

Another issue is that I think you are running tests in multiple threads? We didn't test that, so we need some more carefulness to handle that properly.

Exactly! I assumed C API is supposed to run fine in multithread environment, is this assumption correct?

pepyakin on 19 Jan 2018

It should, that's very important even, but it was never tested ;) Our test harness is just not multithreaded. We should probably add a specific test for this...

kripken on 19 Jan 2018

👍1

Ok, I've updated binaryen to the latest master and getting following two failures:

First:

running 9 tests
Assertion failed: (!ThreadPool::isRunning()), function Thread, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 51.
Process 89480 stopped
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-0f7351d0ba7e4ea7) stopped.
(lldb) bt
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x0000000100376993 binaryen-0f7351d0ba7e4ea7`wasm::Thread::Thread(this=0x0000000102300b50) at threads.cpp:51
    frame #5: 0x0000000100377245 binaryen-0f7351d0ba7e4ea7`wasm::Thread::Thread(this=0x0000000102300b50) at threads.cpp:50
    frame #6: 0x0000000100378bc4 binaryen-0f7351d0ba7e4ea7`std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > wasm::make_unique<wasm::Thread>() at utilities.h:60
    frame #7: 0x0000000100378002 binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::initialize(this=0x0000000102300720, num=8) at threads.cpp:116
    frame #8: 0x0000000100377c84 binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::get() at threads.cpp:157
    frame #9: 0x00000001000d04c7 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000a037970)::$_0::operator()() const at pass.cpp:276
    frame #10: 0x00000001000cee23 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000a038550) at pass.cpp:311
    frame #11: 0x00000001003facc9 binaryen-0f7351d0ba7e4ea7`wasm::WasmValidator::validate(this=0x000070000a038758, module=0x0000000102300190, features=1, flags=2) at wasm-validator.cpp:1029
    frame #12: 0x000000010002bc34 binaryen-0f7351d0ba7e4ea7`::BinaryenModuleValidate(module=0x0000000102300190) at binaryen-c.cpp:2006
    frame #13: 0x000000010000d2f9 binaryen-0f7351d0ba7e4ea7`binaryen::Module::is_valid::h30b6f4c52bdc3dc8 + 57
    frame #14: 0x000000010000b322 binaryen-0f7351d0ba7e4ea7`binaryen::tests::test_hello_world::hfb02bbe837ce977a + 450
    frame #15: 0x0000000100469fc2 binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #16: 0x0000000100469fbd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #17: 0x0000000100469fbd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #18: 0x00000001004acc7f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #19: 0x000000010045a4c1 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #20: 0x000000010045a47c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #21: 0x000000010045a47c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #22: 0x000000010045a329 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #23: 0x000000010045fd58 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #24: 0x000000010045fd42 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #25: 0x000000010045fd42 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #26: 0x00000001004acc7f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #27: 0x0000000100476482 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #28: 0x0000000100476449 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #29: 0x0000000100476449 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #30: 0x00000001004763fc binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #31: 0x0000000100494a78 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #32: 0x0000000100494a75 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #33: 0x000000010049eb59 binaryen-0f7351d0ba7e4ea7`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #34: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #35: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #36: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

and second:

running 9 tests
test to_cstr::tests::test_to_cstr_stash_option ... ok
Assertion failed: (!running), fuAssertion failed: (!ThreadPool::nction work, file /Users/pepyakiisRunning()), function Thread, fn/dev/my/binaryen-rs/binaryen-syile /Users/pepyakin/dev/my/binars/binaryen/src/support/threads.cyen-rs/binaryen-sys/binaryen/srcpp, line 177.
/support/threads.cpp, line 51.
Process 89603 stopped
* thread #2, name = 'tests::test_unreachable', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-0f7351d0ba7e4ea7) stopped.
(lldb) bt
* thread #2, name = 'tests::test_unreachable', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x000000010037913e binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::work(this=0x0000000100c02ba0, doWorkers=size=1)>, std::__1::allocator<std::__1::function<wasm::ThreadWorkState ()> > >&) at threads.cpp:177
    frame #5: 0x00000001000d0981 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x0000700000c5c950)::$_0::operator()() const at pass.cpp:299
    frame #6: 0x00000001000cee23 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x0000700000c5d530) at pass.cpp:311
    frame #7: 0x00000001003facc9 binaryen-0f7351d0ba7e4ea7`wasm::WasmValidator::validate(this=0x0000700000c5d738, module=0x0000000102b00190, features=1, flags=2) at wasm-validator.cpp:1029
    frame #8: 0x000000010002bc34 binaryen-0f7351d0ba7e4ea7`::BinaryenModuleValidate(module=0x0000000102b00190) at binaryen-c.cpp:2006
    frame #9: 0x000000010000d2f9 binaryen-0f7351d0ba7e4ea7`binaryen::Module::is_valid::h30b6f4c52bdc3dc8 + 57
    frame #10: 0x000000010000bbdc binaryen-0f7351d0ba7e4ea7`binaryen::tests::test_unreachable::h57159d1bc306b867 + 524
    frame #11: 0x0000000100469fc2 binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #12: 0x0000000100469fbd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #13: 0x0000000100469fbd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #14: 0x00000001004acc7f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #15: 0x000000010045a4c1 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #16: 0x000000010045a47c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #17: 0x000000010045a47c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #18: 0x000000010045a329 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #19: 0x000000010045fd58 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #20: 0x000000010045fd42 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #21: 0x000000010045fd42 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #22: 0x00000001004acc7f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #23: 0x0000000100476482 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #24: 0x0000000100476449 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #25: 0x0000000100476449 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #26: 0x00000001004763fc binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #27: 0x0000000100494a78 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #28: 0x0000000100494a75 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #29: 0x000000010049eb59 binaryen-0f7351d0ba7e4ea7`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #30: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #31: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #32: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

These failures are not so frequent as with previous version (i.e. with this version I can get 3-4 successful runs in a row). First failure is definitely more frequent than second one.

pepyakin on 25 Jan 2018

Hm, it seems BINARYEN_THREAD_DEBUG uncovers some more failures.

Note that cpp line numbers skewed a little because I added #define BINARYEN_THREAD_DEBUG

running 9 tests
test to_cstr::tests::test_to_cstr_stash_option ... ok
test tests::test_use_same_expr_twice ... ok
test to_cstr::tests::test_use_cases ... ok
[POOL] ::get()
[POOL] ::get()
[POOL] ::get()
[POOL] ::get() creating
[POOL] initialize()
[POOL] reset threads are ready
[POOL] ::get()
[POOL] check if running
[POOL] ::get()
test tests::test_relooper_with_different_module ... ok
[POOL] work() sequentially
[POOL] work() sequentially
[POOL] check if running
(block[THREAD
 (block $block$2$break
0x70000ca4e000]  checking for work
 [POOL] (check if running
test tests::test_unreachable ... ok
[THREAD nop0x70000c242000] )checking for work

  [POOL] (::get()
[THREAD block
0x70000c2c5000   (br ] $checking for work
block$2$break)
  [POOL] )check if running

 [POOL] )::get()

[POOL]  notify thread is ready
(block
  (nop)
[POOL]  ::get()
)
[POOL] )
check if running
[THREAD 0x70000c348000] checking for work
test relooper::tests::test ... [POOL] notify thread is ready
ok
[POOL] notify thread is ready
[POOL] ::get()
[POOL] check if running
[THREAD 0x70000c648000] checking for work
[POOL] ::get()
[POOL] ::get()
[POOL] check if running
[POOL] ::get()
[THREAD 0x70000be3c000] checking for work
[POOL] notify thread is ready
[POOL] work() on threads
[POOL] notify thread is ready
[POOL] check if running
Assertion failed: (doWorkers.size() == num), function work, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/su[THREAD pport/threads.cpp, line 178.
0x70000bebf000] checking for work
[POOL] ::get()
[POOL] ::get()
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] initialize() waiting
[THREAD 0x70000bf42000] checking for work
Process 90265 stopped
* thread #2, name = 'tests::test_simple', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-0f7351d0ba7e4ea7) stopped.
(lldb) bt
* thread #2, name = 'tests::test_simple', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x000000010037a77b binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::work(this=0x0000000100c020d0, doWorkers=size=1)>, std::__1::allocator<std::__1::function<wasm::ThreadWorkState ()> > >&) at threads.cpp:178
    frame #5: 0x00000001000d08d1 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000c5c38f0)::$_0::operator()() const at pass.cpp:299
    frame #6: 0x00000001000ced73 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000c5c44d0) at pass.cpp:311
    frame #7: 0x00000001003fc7c9 binaryen-0f7351d0ba7e4ea7`wasm::WasmValidator::validate(this=0x000070000c5c46d8, module=0x0000000103c00080, features=1, flags=2) at wasm-validator.cpp:1029
    frame #8: 0x000000010002bb84 binaryen-0f7351d0ba7e4ea7`::BinaryenModuleValidate(module=0x0000000103c00080) at binaryen-c.cpp:2006
    frame #9: 0x000000010000d249 binaryen-0f7351d0ba7e4ea7`binaryen::Module::is_valid::h30b6f4c52bdc3dc8 + 57
    frame #10: 0x000000010000b607 binaryen-0f7351d0ba7e4ea7`binaryen::tests::test_simple::h0dd0ae5c0c283f4d + 775
    frame #11: 0x000000010046bac2 binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #12: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #13: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #14: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #15: 0x000000010045bfc1 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #16: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #17: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #18: 0x000000010045be29 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #19: 0x0000000100461858 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #20: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #21: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #22: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #23: 0x0000000100477f82 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #24: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #25: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #26: 0x0000000100477efc binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #27: 0x0000000100496578 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #28: 0x0000000100496575 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #29: 0x00000001004a0659 binaryen-0f7351d0ba7e4ea7`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #30: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #31: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #32: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

running 9 tests
test to_cstr::tests::test_to_cstr_stash_option ... ok
[POOL] ::get()
[POOL] ::get()
[POOL] test tests::test_use_same_expr_twice ... ::get()
ok[POOL]
::get() creating
test to_cstr::tests::test_use_cases ... ok
test tests::test_relooper_with_different_module ... ok
([POOL] blockinitialize()

[POOL]  ::get()
(block $block$2$break
[POOL]  ::get()
 [POOL] (reset threads are ready
nop)
  [POOL] (work() sequentially
block
   (br $block$2$break)
[POOL]   )
work() sequentially
 )
 (block
  (nop)
[POOL]  check if running
)
)
[POOL] check if running
[THREAD 0x70000d1c6000test relooper::tests::test ... ] checking for work
ok
[POOL] test tests::test_unreachable ... check if running
ok
[POOL] ::get()
[THREAD 0x70000d249000] checking for work
[POOL] notify thread is ready
[THREAD 0x70000cdc0000] checking for work
[POOL] check if running
[POOL] ::get()
[POOL] ::get()
[POOL] notify thread is ready
[POOL] check if running
[THREAD 0x70000ce43000] checking for work
[POOL] notify thread is ready
[POOL] check if running
[THREAD 0x70000cec6000] checking for work
[POOL] ::get()
[POOL] ::get()
[POOL] check if running
[THREAD 0x70000d2cc000] checking for work
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] check if running
[POOL] ::get()
[THREAD 0x70000d5cc000] checking for work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x70000d64f000] checking for work
[POOL] initialize() waiting
[POOL] ::get()
[POOL] ::get()
[POOL] ::get()
[POOL] are threads ready?
[POOL] notify thread is ready
[POOL] work() on threads
[POOL] notify thread is ready
[THREAD 0x70000d1c6000] thread waiting
[THREAD 0x70000d249000] thread waiting
[THREAD 0x70000cdc0000] thread waiting
[THREAD 0x70000ce43000] thread waiting
[THREAD 0x70000cec6000] thread waiting
[THREAD 0x70000d2cc000] thread waiting
[THREAD 0x70000d5cc000] thread waiting
[POOL] are threads ready?
[POOL] reset threads are ready
Assertion failed: (old == threads.size()), function resetThreadsAreReady, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 213.
Process 90273 stopped
* thread #2, name = 'tests::test_simple', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-0f7351d0ba7e4ea7) stopped.
(lldb) bt
* thread #2, name = 'tests::test_simple', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x0000000100379fcf binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::resetThreadsAreReady(this=0x0000000102f004b0) at threads.cpp:213
    frame #5: 0x000000010037a878 binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::work(this=0x0000000102f004b0, doWorkers=size=1)>, std::__1::allocator<std::__1::function<wasm::ThreadWorkState ()> > >&) at threads.cpp:182
    frame #6: 0x00000001000d08d1 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000d5478f0)::$_0::operator()() const at pass.cpp:299
    frame #7: 0x00000001000ced73 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000d5484d0) at pass.cpp:311
    frame #8: 0x00000001003fc7c9 binaryen-0f7351d0ba7e4ea7`wasm::WasmValidator::validate(this=0x000070000d5486d8, module=0x0000000102b00420, features=1, flags=2) at wasm-validator.cpp:1029
    frame #9: 0x000000010002bb84 binaryen-0f7351d0ba7e4ea7`::BinaryenModuleValidate(module=0x0000000102b00420) at binaryen-c.cpp:2006
    frame #10: 0x000000010000d249 binaryen-0f7351d0ba7e4ea7`binaryen::Module::is_valid::h30b6f4c52bdc3dc8 + 57
    frame #11: 0x000000010000b607 binaryen-0f7351d0ba7e4ea7`binaryen::tests::test_simple::h0dd0ae5c0c283f4d + 775
    frame #12: 0x000000010046bac2 binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #13: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #14: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #15: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #16: 0x000000010045bfc1 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #17: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #18: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #19: 0x000000010045be29 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #20: 0x0000000100461858 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #21: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #22: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #23: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #24: 0x0000000100477f82 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #25: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #26: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #27: 0x0000000100477efc binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #28: 0x0000000100496578 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #29: 0x0000000100496575 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #30: 0x00000001004a0659 binaryen-0f7351d0ba7e4ea7`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #31: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #32: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #33: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

running 9 tests
test to_cstr::tests::test_to_cstr_stash_option ... ok
[POOL] test tests::test_use_same_expr_twice ... ::get()
ok
[POOL] ::get()
test to_cstr::tests::test_use_cases ... [POOL] ::get()
ok
[POOL] ::get() creating
[POOL] initialize()
[POOL] reset threads are ready
[POOL] check if running
[POOL] ::get()
test tests::test_relooper_with_different_module ... ok[POOL]
check if running
[POOL] ::get()
[POOL] work() on threads
[THREAD 0x7000073ab000(block] checking for work

[POOL]  work() on threads
(block $block$2$break
[THREAD Assertion failed: (!running), function work, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 179.
 0x700006da2000 ] (checking for work
nop)
[POOL]  check if running
Process 90277 stopped
* thread #2, name = 'tests::test_unreachable', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-0f7351d0ba7e4ea7) stopped.
(lldb) bt
* thread #2, name = 'tests::test_unreachable', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x000000010037a7fc binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::work(this=0x0000000103000130, doWorkers=size=1)>, std::__1::allocator<std::__1::function<wasm::ThreadWorkState ()> > >&) at threads.cpp:179
    frame #5: 0x00000001000d08d1 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x0000700007326950)::$_0::operator()() const at pass.cpp:299
    frame #6: 0x00000001000ced73 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x0000700007327530) at pass.cpp:311
    frame #7: 0x00000001003fc7c9 binaryen-0f7351d0ba7e4ea7`wasm::WasmValidator::validate(this=0x0000700007327738, module=0x0000000100c09e50, features=1, flags=2) at wasm-validator.cpp:1029
    frame #8: 0x000000010002bb84 binaryen-0f7351d0ba7e4ea7`::BinaryenModuleValidate(module=0x0000000100c09e50) at binaryen-c.cpp:2006
    frame #9: 0x000000010000d249 binaryen-0f7351d0ba7e4ea7`binaryen::Module::is_valid::h30b6f4c52bdc3dc8 + 57
    frame #10: 0x000000010000bb2c binaryen-0f7351d0ba7e4ea7`binaryen::tests::test_unreachable::h57159d1bc306b867 + 524
    frame #11: 0x000000010046bac2 binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #12: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #13: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #14: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #15: 0x000000010045bfc1 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #16: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #17: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #18: 0x000000010045be29 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #19: 0x0000000100461858 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #20: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #21: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #22: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #23: 0x0000000100477f82 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #24: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #25: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #26: 0x0000000100477efc binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #27: 0x0000000100496578 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #28: 0x0000000100496575 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #29: 0x00000001004a0659 binaryen-0f7351d0ba7e4ea7`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #30: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #31: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #32: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

running 9 tests
test tests::test_use_same_expr_twice ... ok
[POOL] ::get()
[POOL] test to_cstr::tests::test_to_cstr_stash_option ... ::get()
[POOL] ok::get()

[POOL] ::get() creating
[POOL] initialize()
[POOL] reset threads are ready
[POOL] check if running
test to_cstr::tests::test_use_cases ... [POOL] ::get()
ok
[POOL] ::get()
test tests::test_relooper_with_different_module ... ok[POOL]
work() on threads
[POOL] check if running
[THREAD Assertion failed: (!ThreadPool::isRunning()), function Thread, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 53.
0x700008cc0000(] blockchecking for work

 (blockProcess 90297 stopped
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-0f7351d0ba7e4ea7) stopped.
(lldb) bt
* thread #2, name = 'tests::test_hello_world', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x00000001003768e3 binaryen-0f7351d0ba7e4ea7`wasm::Thread::Thread(this=0x0000000100c02830) at threads.cpp:53
    frame #5: 0x0000000100377a25 binaryen-0f7351d0ba7e4ea7`wasm::Thread::Thread(this=0x0000000100c02830) at threads.cpp:52
    frame #6: 0x000000010037a074 binaryen-0f7351d0ba7e4ea7`std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > wasm::make_unique<wasm::Thread>() at utilities.h:60
    frame #7: 0x000000010037904c binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::initialize(this=0x0000000100c02730, num=8) at threads.cpp:118
    frame #8: 0x0000000100378a02 binaryen-0f7351d0ba7e4ea7`wasm::ThreadPool::get() at threads.cpp:159
    frame #9: 0x00000001000d0417 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x000070000842f970)::$_0::operator()() const at pass.cpp:276
    frame #10: 0x00000001000ced73 binaryen-0f7351d0ba7e4ea7`wasm::PassRunner::run(this=0x0000700008430550) at pass.cpp:311
    frame #11: 0x00000001003fc7c9 binaryen-0f7351d0ba7e4ea7`wasm::WasmValidator::validate(this=0x0000700008430758, module=0x0000000100d07d20, features=1, flags=2) at wasm-validator.cpp:1029
    frame #12: 0x000000010002bb84 binaryen-0f7351d0ba7e4ea7`::BinaryenModuleValidate(module=0x0000000100d07d20) at binaryen-c.cpp:2006
    frame #13: 0x000000010000d249 binaryen-0f7351d0ba7e4ea7`binaryen::Module::is_valid::h30b6f4c52bdc3dc8 + 57
    frame #14: 0x000000010000b272 binaryen-0f7351d0ba7e4ea7`binaryen::tests::test_hello_world::hfb02bbe837ce977a + 450
    frame #15: 0x000000010046bac2 binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] test::run_test::{{closure}} at lib.rs:1510 [opt]
    frame #16: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> [inlined] core::ops::function::FnOnce::call_once<closure,(())> at function.rs:223 [opt]
    frame #17: 0x000000010046babd binaryen-0f7351d0ba7e4ea7`test::{{impl}}::call_box<(),closure> at lib.rs:142 [opt]
    frame #18: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #19: 0x000000010045bfc1 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #20: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #21: 0x000000010045bf7c binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> [inlined] test::run_test::run_test_inner::{{closure}} at lib.rs:1447 [opt]
    frame #22: 0x000000010045be29 binaryen-0f7351d0ba7e4ea7`std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> at backtrace.rs:133 [opt]
    frame #23: 0x0000000100461858 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> at mod.rs:406 [opt]
    frame #24: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> [inlined] std::panic::{{impl}}::call_once<(),closure> at panic.rs:300 [opt]
    frame #25: 0x0000000100461842 binaryen-0f7351d0ba7e4ea7`std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> at panicking.rs:480 [opt]
    frame #26: 0x00000001004ae77f binaryen-0f7351d0ba7e4ea7`panic_unwind::__rust_maybe_catch_panic at lib.rs:101 [opt]
    frame #27: 0x0000000100477f82 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> at panicking.rs:459 [opt]
    frame #28: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> at panic.rs:365 [opt]
    frame #29: 0x0000000100477f49 binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> [inlined] std::thread::{{impl}}::spawn::{{closure}}<closure,()> at mod.rs:405 [opt]
    frame #30: 0x0000000100477efc binaryen-0f7351d0ba7e4ea7`alloc::boxed::{{impl}}::call_box<(),closure> at boxed.rs:817 [opt]
    frame #31: 0x0000000100496578 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread [inlined] alloc::boxed::{{impl}}::call_once<(),()> at boxed.rs:827 [opt]
    frame #32: 0x0000000100496575 binaryen-0f7351d0ba7e4ea7`std::sys_common::thread::start_thread at thread.rs:24 [opt]
    frame #33: 0x00000001004a0659 binaryen-0f7351d0ba7e4ea7`std::sys::unix::thread::{{impl}}::new::thread_start at thread.rs:90 [opt]
    frame #34: 0x00007fff9033493b libsystem_pthread.dylib`_pthread_body + 180
    frame #35: 0x00007fff90334887 libsystem_pthread.dylib`_pthread_start + 286
    frame #36: 0x00007fff9033408d libsystem_pthread.dylib`thread_start + 13

pepyakin on 25 Jan 2018

Thanks, I think I see what's wrong. Fixes in #1389.

kripken on 25 Jan 2018

It seems this PR have an error different error

<stripped>
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] ::get()
[POOL] ::get()
[POOL] ::get()
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009089000] thread waiting
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] thread waiting
[THREAD 0x700009512000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x700009a98000] thread waiting
[POOL] notify thread is ready
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x70000910c000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009089000] checking for work
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] ::get()
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x70000910c000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009089000] thread waiting
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[THREAD 0x700009512000] thread waiting
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009a98000] thread waiting
[POOL] are threads ready?
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009089000] checking for work
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] doing work
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[POOL] ::get()
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] thread waiting
[THREAD 0x70000910c000] thread waiting
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] notify thread is ready
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x700009089000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009a98000] thread waiting
[POOL] ::get()
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x700009089000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009089000] checking for work
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009089000] thread waiting
[THREAD 0x70000910c000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009512000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[THREAD 0x70000948f000] thread waiting
[POOL] ::get()
[THREAD 0x700009a98000] thread waiting
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009089000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] doing work
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x70000910c000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x70000948f000] thread waiting
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x700009a98000] thread waiting
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009089000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009089000] checking for work
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[POOL] ::get()
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009089000] thread waiting
[THREAD 0x70000910c000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] thread waiting
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009512000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009a98000] thread waiting
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009089000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[POOL] ::get()
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009089000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000910c000] thread waiting
[THREAD 0x70000918f000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009a98000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009b1b000] thread waiting
[THREAD 0x70000948f000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009089000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] doing work
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[POOL] ::get()
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] notify thread is ready
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x700009089000] thread waiting
[THREAD 0x70000910c000] thread waiting
[THREAD 0x70000918f000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009512000] thread waiting
[POOL] ::get()
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009a98000] thread waiting
[POOL] ::get()
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x70000948f000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009089000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] doing work
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[THREAD 0x700009089000] getPoolFromWorker: after creation
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x70000910c000] thread waiting
[THREAD 0x70000948f000] thread waiting
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x700009089000] thread waiting
[THREAD 0x700009512000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x700009a98000] thread waiting
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009089000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[POOL] ::get()
[POOL] ::get()
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x700009089000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000910c000] thread waiting
[POOL] notify thread is ready
[THREAD 0x70000918f000] thread waiting
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[THREAD 0x70000948f000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009a98000] thread waiting
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] checking for work
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[POOL] ::get()
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] notify thread is ready
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x70000948f000] thread waiting
[THREAD 0x70000910c000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[THREAD 0x700009089000] getPoolFromWorker: after creation
[POOL] ::get()
[THREAD 0x700009a98000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[POOL] notify thread is ready
[POOL] notify thread is ready
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[THREAD 0x700009089000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009089000] checking for work
[THREAD 0x70000948f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000918f000] doing work
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[POOL] ::get()
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] ::get()
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] ::get()
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x700009089000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] thread waiting
[POOL] notify thread is ready
[THREAD 0x70000910c000] thread waiting
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[POOL] notify thread is ready
[THREAD 0x70000948f000] thread waiting
[THREAD 0x700009a98000] thread waiting
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
[POOL] ::get()
[POOL] ::get()
[POOL] work() on threads
[POOL] running = true
[POOL] reset threads are ready
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000948f000] checking for work
[THREAD 0x700009089000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] doing work
[THREAD 0x700009089000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000910c000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000910c000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x70000918f000] checking for work
[THREAD 0x700009e1b000] work sent
[THREAD 0x70000948f000] getPoolFromWorker: after creation
[THREAD 0x70000910c000] getPoolFromWorker: after creation
[THREAD 0x70000918f000] doing work
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009512000] checking for work
[POOL] ::get()
[POOL] ::get()
[THREAD 0x70000918f000] getPoolFromWorker: after creation
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009512000] doing work
[POOL] notify thread is ready
[POOL] notify thread is ready
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009595000] checking for work
[THREAD 0x700009512000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009595000] doing work
[POOL] ::get()
[THREAD 0x700009e1b000] send work to thread
[THREAD 0x700009a98000] checking for work
[THREAD 0x700009595000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[THREAD 0x700009e1b000] work sent
[THREAD 0x700009a98000] doing work
[POOL] ::get()
[POOL] main thread waiting
[THREAD 0x700009b1b000] checking for work
[THREAD 0x700009a98000] getPoolFromWorker: after creation
[POOL] notify thread is ready
[POOL] are threads ready?
[THREAD 0x700009b1b000] doing work
[POOL] ::get()
[THREAD 0x70000948f000] thread waiting
[THREAD 0x700009b1b000] getPoolFromWorker: after creation
[THREAD 0x70000910c000] thread waiting
[THREAD 0x70000918f000] thread waiting
[POOL] notify thread is ready
[THREAD 0x700009512000] thread waiting
[THREAD 0x700009595000] thread waiting
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x700009089000] getPoolFromWorker: after creation
[THREAD 0x700009a98000] thread waiting
[POOL] notify thread is ready
[POOL] are threads ready?
[POOL] ::get()
[THREAD 0x700009b1b000] thread waiting
[POOL] are threads ready?
[POOL] notify thread is ready
[THREAD 0x700009089000] thread waiting
[POOL] are threads ready?
[POOL] main thread waiting
[POOL] running = false
[POOL] work() is done
test tools::tests::test_translate_to_fuzz ... ok

test result: ok. 9 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

[THREAD 0x7fff990373c0] getPoolFromWorker: after creation
Assertion failed: (pool), function getPoolFromWorker, file /Users/pepyakin/dev/my/binaryen-rs/binaryen-sys/binaryen/src/support/threads.cpp, line 65.
Process 45913 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
    frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff90249d42 <+10>: jae    0x7fff90249d4c            ; <+20>
    0x7fff90249d44 <+12>: movq   %rax, %rdi
    0x7fff90249d47 <+15>: jmp    0x7fff90242caf            ; cerror_nocancel
    0x7fff90249d4c <+20>: retq
Target 0: (binaryen-8ffc9f51d13f63b0) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
  * frame #0: 0x00007fff90249d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90337457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff901af420 libsystem_c.dylib`abort + 129
    frame #3: 0x00007fff90176893 libsystem_c.dylib`__assert_rtn + 320
    frame #4: 0x0000000100377849 binaryen-8ffc9f51d13f63b0`wasm::getPoolFromWorker() at threads.cpp:65
    frame #5: 0x00000001003785f5 binaryen-8ffc9f51d13f63b0`wasm::Thread::~Thread(this=0x00000001036001f0) at threads.cpp:78
    frame #6: 0x00000001003789a5 binaryen-8ffc9f51d13f63b0`wasm::Thread::~Thread(this=0x00000001036001f0) at threads.cpp:77
    frame #7: 0x000000010037c1a7 binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::default_delete<wasm::Thread>::operator(this=0x0000000100c09db8, __ptr=0x00000001036001f0)(wasm::Thread*) const at memory:2397
    frame #8: 0x000000010037c186 binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >::reset(this=0x0000000100c09db8, __p=0x0000000000000000) at memory:2603
    frame #9: 0x000000010037c133 binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >::~unique_ptr(this=0x0000000100c09db8) at memory:2571
    frame #10: 0x000000010037c133 binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >::~unique_ptr(this=0x0000000100c09db8) at memory:2571
    frame #11: 0x000000010037c133 binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > >::destroy(this=0x0000000103100230, __p=0x0000000100c09db8) at memory:1838
    frame #12: 0x000000010037c0ff binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] void std::__1::allocator_traits<std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::__destroy<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > >(__a=0x0000000103100230, __p=0x0000000100c09db8) at memory:1706
    frame #13: 0x000000010037c0ec binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] void std::__1::allocator_traits<std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::destroy<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > >(__a=0x0000000103100230, __p=0x0000000100c09db8) at memory:1574
    frame #14: 0x000000010037c0d3 binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::__destruct_at_end(this=0x0000000103100220, __new_last=0x0000000100c09d80) at vector:417
    frame #15: 0x000000010037c05e binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base() [inlined] std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::clear(this=0x0000000103100220) at vector:361
    frame #16: 0x000000010037c03f binaryen-8ffc9f51d13f63b0`std::__1::__vector_base<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~__vector_base(this=0x0000000103100220) at vector:444
    frame #17: 0x000000010037bff5 binaryen-8ffc9f51d13f63b0`std::__1::vector<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~vector(this=0x0000000103100220 size=1) at vector:450
    frame #18: 0x000000010037bfd5 binaryen-8ffc9f51d13f63b0`std::__1::vector<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> >, std::__1::allocator<std::__1::unique_ptr<wasm::Thread, std::__1::default_delete<wasm::Thread> > > >::~vector(this=0x0000000103100220 size=1) at vector:450
    frame #19: 0x000000010037bfac binaryen-8ffc9f51d13f63b0`wasm::ThreadPool::~ThreadPool(this=0x0000000103100220) at threads.h:72
    frame #20: 0x000000010037bf75 binaryen-8ffc9f51d13f63b0`wasm::ThreadPool::~ThreadPool(this=0x0000000103100220) at threads.h:72
    frame #21: 0x0000000100376d53 binaryen-8ffc9f51d13f63b0`std::__1::unique_ptr<wasm::ThreadPool, std::__1::default_delete<wasm::ThreadPool> >::~unique_ptr() [inlined] std::__1::default_delete<wasm::ThreadPool>::operator(this=0x0000000100564500, __ptr=0x0000000103100220)(wasm::ThreadPool*) const at memory:2397
    frame #22: 0x0000000100376d38 binaryen-8ffc9f51d13f63b0`std::__1::unique_ptr<wasm::ThreadPool, std::__1::default_delete<wasm::ThreadPool> >::~unique_ptr() [inlined] std::__1::unique_ptr<wasm::ThreadPool, std::__1::default_delete<wasm::ThreadPool> >::reset(this=0x0000000100564500, __p=0x0000000000000000) at memory:2603
    frame #23: 0x0000000100376ceb binaryen-8ffc9f51d13f63b0`std::__1::unique_ptr<wasm::ThreadPool, std::__1::default_delete<wasm::ThreadPool> >::~unique_ptr() [inlined] std::__1::unique_ptr<wasm::ThreadPool, std::__1::default_delete<wasm::ThreadPool> >::~unique_ptr(this=0x0000000100564500) at memory:2571
    frame #24: 0x0000000100376ceb binaryen-8ffc9f51d13f63b0`std::__1::unique_ptr<wasm::ThreadPool, std::__1::default_delete<wasm::ThreadPool> >::~unique_ptr(this=0x0000000100564500) at memory:2571
    frame #25: 0x00007fff901b0178 libsystem_c.dylib`__cxa_finalize_ranges + 332
    frame #26: 0x00007fff901b04b2 libsystem_c.dylib`exit + 55
    frame #27: 0x00007fff9011b23c libdyld.dylib`start + 8

pepyakin on 26 Jan 2018

Interesting... it looks like on your machine when a c++ unique ptr is destroyed, it first clears the value, then destroys the object. So the workers can't find the pool when they destroy themselves. That actually seems odd since it seems like if it were defined behavior, we'd see the same on all machines, and it only happens on yours, which makes me wonder if it isn't undefined behavior in C++...

Anyhow, the fix is simple, to not have them go through a global unique_ptr as they currently do, I pushed a refactor with that to that branch (which seems nicer anyhow).

I'm not able to see that issue though, so I can't verify it fixes what you see, please test it if you can.

kripken on 26 Jan 2018

I can confirm that this fix works!

FWIW, I'm running macOS 10.12.6, with clang version Apple LLVM version 9.0.0 (clang-900.0.39.2) (have no idea how this version scheme is mapped to the original LLVM's)

pepyakin on 26 Jan 2018

🎉1

Great, thanks!

I wonder if this depends on the OS somehow, actually (I'm on linux). That is, maybe how processes are torn down is different, and on linux it "skips" over the potential issue, while on mac it doesn't.

kripken on 26 Jan 2018

I'm no C++ language lawyer, but I believe this is UB. This SO answer gives some clues. Basically, the lifetime of the unique_ptr object ends when its lifetime ends, which is at the start of the call to the destructor. At that point, accessing members of the object is UB.

binji on 26 Jan 2018

Hmm, interesting. In that case, this might still be UB after that PR? Although it depends on whether the lifetype of the unique_ptr is identical to that of what it refers to, and whether our ThreadPool and Thread have "trivial destructors" in the sense of that link (I'd hope yes, but I'm not sure about the mutexes they use), and probably some other details I really don't understand...

kripken on 26 Jan 2018

Anything with a user-provided destructor is not trivial.
So IIRC the issue is that the global thread pool unique_ptr object is destroyed, during which its destructor destroys the ThreadPool object. During this destruction, its unique_ptrs are destroyed, calling the threads' destructors, which call ThreadPool::isRunning() through their parent pointer. isRunning then calls member functions on the global thread pool unique_ptr.

According to [class.cdtor]/p4 member functions of a class can be called during its construction or destruction (including during construction/destruction of non-static data members). So calling ThreadPool::isRunning() during the destruction of the members is ok. Calling member functions on the global unique_ptr member object is also ok for the same reason. I think It's even OK to access data members on the thread pool because its destructor hasn't finished yet (members are destroyed after the user destructor is called). But the data members in a unique_ptr are just pointers, and the destructor is free to frob them as it pleases. So I think it's actually totally legit for the destructor to, e.g. copy the member pointer to a temp ptr, set the member ptr to null, and then delete the temp ptr.

In the new code, during this process, ThreadPool::isRunning() calls the boolean conversion and operator-> on the global unique_ptr (while its destructor is still on the stack), it's relying on that destructor keeping the state consistent (i.e. nulling the member pointer before calling delete). That seems... fragile. And I haven't even started to think about possible race conditions there.

dschuff on 27 Jan 2018

👍1

Right, good point, that's all quite bad. isRunning shouldn't be doing all that extra work with the global pointer, it should just directly access running. Fix coming up.

kripken on 27 Jan 2018

But all this does make me agree more with @binji in https://github.com/WebAssembly/binaryen/pull/1389#issuecomment-360889374

dschuff on 27 Jan 2018

Was this page helpful?

0 / 5 - 0 ratings