From: samuel@... Date: 2020-11-20T01:31:12+00:00 Subject: [ruby-core:100954] [Ruby master Bug#16782] `lock': deadlock; recursive locking (ThreadError) in 2.7.1 Issue #16782 has been updated by ioquatix (Samuel Williams). There is no locking on that line: https://github.com/socketry/async/blob/v1.24.2/lib/async/wrapper.rb#L215 Maybe it happens somewhere inside CRuby or nio4r extension. ---------------------------------------- Bug #16782: `lock': deadlock; recursive locking (ThreadError) in 2.7.1 https://bugs.ruby-lang.org/issues/16782#change-88609 * Author: ioquatix (Samuel Williams) * Status: Open * Priority: Normal * Assignee: ko1 (Koichi Sasada) * Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN ---------------------------------------- Using the latest `async-http` repo: ``` % bundle exec rspec spec/async/http/performance_spec.rb Traceback (most recent call last): 11: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/task.rb:258:in `block in make_fiber' 10: from /home/samuel/.gem/ruby/2.7.1/gems/async-io-1.28.0/lib/async/io/socket.rb:73:in `block in accept' 9: from /home/samuel/.gem/ruby/2.7.1/gems/async-io-1.28.0/lib/async/io/server.rb:32:in `block in accept_each' 8: from /home/samuel/Documents/socketry/async-http/lib/async/http/server.rb:67:in `accept' 7: from /home/samuel/Documents/socketry/async-http/lib/async/http/protocol/http1/connection.rb:80:in `close' 6: from /home/samuel/.gem/ruby/2.7.1/gems/protocol-http1-0.12.0/lib/protocol/http1/connection.rb:135:in `close' 5: from /home/samuel/.gem/ruby/2.7.1/gems/async-io-1.28.0/lib/async/io/stream.rb:224:in `close' 4: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:164:in `close' 3: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `cancel_monitor' 2: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `close' 1: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `deregister' /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `lock': SIGTERM (SignalException) 9: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/forked.rb:64:in `block in spawn' 8: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork' 7: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork' 6: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/forked.rb:67:in `block (2 levels) in spawn' 5: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/controller.rb:47:in `block in async' 4: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:58:in `run' 3: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:58:in `ensure in run' 2: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:250:in `close' 1: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:250:in `close' /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:250:in `lock': deadlock; recursive locking (ThreadError) runs benchmark Finished in 4.5 seconds (files took 0.2483 seconds to load) 2 examples, 0 failures % ruby --version ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux] ``` About 1 in 10-100 runs will trigger this result. I also tried current head and could reproduce: ``` Running 2s test @ http://127.0.0.1:9294/ 8 threads and 8 connections Thread Stats Avg Stdev Max +/- Stdev Latency 10.35ms 14.03ms 46.73ms 78.86% Req/Sec 0.99k 454.60 2.30k 63.80% 16122 requests in 2.10s, 787.51KB read Requests/sec: 7675.89 Transfer/sec: 374.94KB 4.66s error: Async::Task [oid=0x1360] [pid=69337] [2020-04-13 15:40:21 +1200] | ThreadError: deadlock; recursive locking | ��� /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `lock' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `deregister' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `close' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `cancel_monitor' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:164 in `close' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:78 in `ensure in block (2 levels) in bind' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:78 in `block (2 levels) in bind' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/task.rb:258 in `block in make_fiber' | Caused by Async::Stop: Async::Stop | ��� /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/task.rb:66 in `yield' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:233 in `wait_for' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:124 in `wait_readable' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/generic.rb:220 in `async_send' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/socket.rb:62 in `accept' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/server.rb:36 in `accept_each' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:104 in `block in accept' | /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:76 in `block (2 levels) in bind' | /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/task.rb:258 in `block in make_fiber' Traceback (most recent call last): 9: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:64:in `block in spawn' 8: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork' 7: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork' 6: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:67:in `block (2 levels) in spawn' 5: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/controller.rb:47:in `block in async' 4: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:56:in `run' 3: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:234:in `run' 2: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:204:in `run_once' 1: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:204:in `select' /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:204:in `lock': SIGTERM (SignalException) 9: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:64:in `block in spawn' 8: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork' 7: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork' 6: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:67:in `block (2 levels) in spawn' 5: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/controller.rb:47:in `block in async' 4: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:58:in `run' 3: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:58:in `ensure in run' 2: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:250:in `close' 1: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:250:in `close' /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:250:in `lock': deadlock; recursive locking (ThreadError) runs benchmark Finished in 4.56 seconds (files took 0.31919 seconds to load) 2 examples, 0 failures ``` It's relatively straight forward to reproduce. -- https://bugs.ruby-lang.org/ Unsubscribe: