Deadlocks in Rails Console

[mlh758]

Steps to reproduce

With the Rails console open, try loading a record with something like Model.find 123

This is tricky because it doesn't happen for every DB access, certainly doesn't happen for everyone using this tool, and only occurs in development mode in the console.

Expected behavior

I should get a record from the database.

Actual behavior

CPU usage spikes, console sits forever, stuck.
Edit: I initially thought it dropped back down but that was just me attaching the debugger and pausing execution.

System configuration

Rails version: 5.1.6.1

Oracle enhanced adapter version: 1.8.2

Ruby version: ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]

Oracle Database version: 11g

I'm not convinced this is entirely the fault of Oracle enhanced. I grabbed some stack traces and the main thread is blocked on a system call:
#1 0x0000000115b18e1f in nttfprd () from .../instantclient_12_1/libclntsh.dylib.12.1

However, once I tried to interact with Ruby using gdb I caused a segfault and accidentally got the Ruby stack trace I was looking for the ugly way:

-- Ruby level backtrace information ----------------------------------------
/Users/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.1.5/lib/listen/internals/thread_pool.rb:6:in `block in add'
/Users/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.1.5/lib/listen/adapter/base.rb:78:in `block in start'
/Users/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:55:in `_run'
/Users/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:71:in `_run_worker'
/Users/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:55:in `run'
/Users/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:55:in `read'

That to me reads like listen is at least involved here, but this only locks up when I make a call to the database. This happens just about every time I launch a Rails console, but it doesn't seem to happen with Rails server or through ActiveJob.

Here is a gist with the actual traces. One is a flat trace I grabbed from gdb where you can see the call in instantclient at the top of the main thread.

The output from sample is annoyingly noisy, but you can see the call to thread_pool which is what I believe was at the top of the Ruby stack trace. Down at the leaves of that call tree there is an awful lot of _pthread_mutex_lock_wait which I think is called here where the interpreter is trying to acquire the VM lock.

I'm also going to try swapping out my version of Oracle Instant Client and see if that helps.

[mlh758]

This seems to happen specifically when I access a class for the first time, and I see the oci8_do_describe call which seems to be in oci8_call_without_gvl. I wonder if that's allowing it to misbehave somehow?

The listen threads seem to be under rb_thread_io_blocking_region which after reading around a little more seems to be used to release the GVL so other Ruby stuff can continue on while you wait on IO. It makes sense that they would be waiting, although maybe their waiting for the lock is contending with the oci8 call?

I'm a bit out of my depth. I upgraded instant client but I can still cause the deadlocks.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mlh758]

Still a problem stale bot.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[mlh758]

:(

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.