ExecJS exhibits a deadlock when multiple threads are executing with connection_pool size > 1

[mchristen]

There seems to be a deadlock issue with ExecJS -> therubyracer and using a threaded server like Puma.

See the issue here rubyjs/therubyracer#270 for some discussion.

I was able to reproduce this deadlock consistently on my local machine using the following setup:

Using the latest released version of

Rails
Puma
ExecJS
therubyracer
libv8

Puma configured to run 8 Worker processes with 8 threads each.
Server side rendering configured to use a connection_pool of size 8, since each process will only have 8 worker threads.

Using a tool like JMeter to generate significant load/traffic to the Puma workers eventually every forked process that Puma spawns deadlocks and halts request processing.

There are 2 different traces exhibited by the 8 different worker processes, but always end up being deadlocked in the same place inside of ExecJS.

       from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/rails/view_helper.rb:12:in `block in react_component'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering.rb:15:in `render'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:60:in `with'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:60:in `handle_interrupt'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:61:in `block in with'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:89:in `checkout'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:76:in `pop'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:76:in `synchronize'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:77:in `block in pop'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:77:in `loop'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:81:in `block (2 levels) in pop'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:169:in `try_create'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:169:in `call'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering.rb:11:in `block in reset_pool'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering.rb:21:in `create_renderer'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering.rb:21:in `new'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering/sprockets_renderer.rb:14:in `initialize'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/module.rb:27:in `compile'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/runtime.rb:44:in `compile'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/runtime.rb:44:in `new'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/ruby_racer_runtime.rb:9:in `initialize'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/ruby_racer_runtime.rb:73:in `lock'
        from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/ruby_racer_runtime.rb:73:in `Locker'

  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/rails/view_helper.rb:12:in `block in react_component'                                                                                                                                                            
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering.rb:15:in `render'                                                                                                                                                                               
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:60:in `with'                                                                                                                                                                                                   
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:60:in `handle_interrupt'                                                                                                                                                                                       
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:63:in `block in with'                                                                                                                                                                                          
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:63:in `handle_interrupt'                                                                                                                                                                                       
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:64:in `block (2 levels) in with'                                                                                                                                                                               
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering.rb:16:in `block in render'                                                                                                                                                                      
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/bundler/gems/react-rails-2ac01d93eee6/lib/react/server_rendering/sprockets_renderer.rb:46:in `render'                                                                                                                                                            
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/ruby_racer_runtime.rb:32:in `eval'                                                                                                                                                                                                  
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/ruby_racer_runtime.rb:73:in `lock'                                                                                                                                                                                                  
  from /home/matt/.rbenv/versions/2.2.1/lib/ruby/gems/2.2.0/gems/execjs-2.5.2/lib/execjs/ruby_racer_runtime.rb:73:in `Locker'                                                            

Using the exact same setup, but setting the react server_rendering pool size to be 1 I am able to avoid the deadlock and performance doesn't seem to change much. Perhaps using a connection_pool is a premature optimization that comes with some potential fatal side effects from underlying thread safety bugs.

The only big change I notice about performance is that latency seems to have a higher deviation now, but requests/minute hasn't really changed much when running at full capacity.

[mchristen]

I've been stress testing this setup now for quite some time and everything seems to be working just fine. I've managed to put a million requests through the 8 processes w/ 8 threads each setup using only a single ExecJS context.

Before when using a pool to match the size of threads I could maybe get about 1000 requests through a process before it would deadlock.

Note that this is really only a problem when your system is under decent load and there is some contention for the locks.

It looks like libv8 has its own GIL and I'm not sure how much I/O would be going on during rendering so that's why I think performance has been OK with only one ExecJS context.

[rmosolgo]

Wow, thanks for sharing this really detailed info! Yeah, server rendering was added before I was involved (PR and it looks like connection pool was added but not tested.

Certainly looks like a global lock: https://github.com/rails/execjs/blob/master/lib/execjs/ruby_racer_runtime.rb#L73-L79

I'm not in a great situation to test this rigorously because we don't prerender in production. But it would be great to test the efficacy of connection pooling with different ExecJS runtimes (eg, does the Node.js have the same problem?)

[mchristen]

Yeah, I thought about testing with Node.js instead of therubyracer, I just haven't had the time yet.

There's nothing inherently wrong with the connection_pool logic, but there's a lot of locking going on in ExecJS, therubyracer and libv8 and there is probably some bug in MRI or one of those gems causing the problem.

I've also through that maybe a thread is crashing while rendering inside of the ExecJS context and not releasing a lock, but I can't find any evidence of unhandled exceptions occurring prior to the process locking up.

I'll have some time in the next few days to get back to this and stick a debugger on it again to try and get some more information. I will also test it with Node.js to see if that helps or is better/worse for performance.

[rmosolgo]

Curiosity was killing me, here's a benchmark I ran, what do you think?

#290

[rmosolgo]

updating code and docs here: https://github.com/rmosolgo/react-rails/commit/850f2b89695cc0974a7444834db815b0b2cb6e89

[justin808]

@cowboyd, any chance that you can comment here?

[justin808]

FYI: https://github.com/cowboyd/therubyracer/tree/upgrade-to-v8-4.5 When this comes out, that will enable multi-threaded rendering, hopefully.