brianmario / mysql2

A modern, simple and very fast Mysql library for Ruby - binding to libmysql
http://github.com/brianmario/mysql2
MIT License
2.24k stars 550 forks source link

mysql_ping causing Thread interrupts in Phusion passenger #777

Open technopoetic opened 8 years ago

technopoetic commented 8 years ago

We've been having this issue in production for quite a while now, most of this year, actually. It typically occurs several times a day, but it seems random. So far I haven't been able to track down what's causing it, but my hypothesis is that when mysql_ping initiates a reconnect, it interrupts the current thread, causing Phusion passenger to raise a FATAL exception. I've also had virtually no luck reproducing it locally. Do you guys have any insight?

The fatal exception is: PhusionPassenger::RequestHandler::ThreadHandler::Interrupted

Stacktrace:

[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/mysql2_adapter.rb:91 :in `ping`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/mysql2_adapter.rb:91 :in `active?`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract_adapter.rb:328 :in `verify!`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:456 :in `block in checkout_and_verify`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:88 :in `__run_callbacks__`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:778 :in `_run_checkout_callbacks`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:455 :in `checkout_and_verify`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:351 :in `block in checkout`
/opt/rbenv/versions/2.2.3/lib/ruby/2.2.0/monitor.rb:211 :in `mon_synchronize`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:348 :in `checkout`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:263 :in `block in connection`
/opt/rbenv/versions/2.2.3/lib/ruby/2.2.0/monitor.rb:211 :in `mon_synchronize`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:262 :in `connection`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:571 :in `retrieve_connection`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_handling.rb:113 :in `retrieve_connection`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_handling.rb:87 :in `connection`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/query_cache.rb:31 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:653 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/callbacks.rb:29 :in `block in call`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:88 :in `__run_callbacks__`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:778 :in `_run_call_callbacks`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:81 :in `run_callbacks`
[GEM_ROOT]/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/callbacks.rb:27 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/remote_ip.rb:78 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/debug_exceptions.rb:17 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/show_exceptions.rb:30 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:38 :in `call_app`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:20 :in `block in call`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/tagged_logging.rb:68 :in `block in tagged`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/tagged_logging.rb:26 :in `tagged`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/tagged_logging.rb:68 :in `tagged`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:20 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/request_id.rb:21 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/rack-1.6.4/lib/rack/methodoverride.rb:22 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/rack-1.6.4/lib/rack/runtime.rb:18 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/activesupport-4.2.5.2/lib/active_support/cache/strategy/local_cache_middleware.rb:28 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/rack-1.6.4/lib/rack/sendfile.rb:113 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/engine.rb:518 :in `call`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/application.rb:165 :in `call`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/railtie.rb:194 :in `public_send`
[GEM_ROOT]/gems/railties-4.2.5.2/lib/rails/railtie.rb:194 :in `method_missing`
[GEM_ROOT]/gems/newrelic_rpm-3.14.0.305/lib/new_relic/agent/instrumentation/middleware_tracing.rb:78 :in `call`
/usr/lib64/ruby/gems/1.8/gems/passenger-enterprise-server-4.0.59/lib/phusion_passenger/rack/thread_handler_extension.rb:58 :in `process_request`
/usr/lib64/ruby/gems/1.8/gems/passenger-enterprise-server-4.0.59/lib/phusion_passenger/request_handler/thread_handler.rb:126 :in `accept_and_process_next_request`
/usr/lib64/ruby/gems/1.8/gems/passenger-enterprise-server-4.0.59/lib/phusion_passenger/request_handler/thread_handler.rb:94 :in `main_loop`
/usr/lib64/ruby/gems/1.8/gems/passenger-enterprise-server-4.0.59/lib/phusion_passenger/request_handler.rb:479 :in `block (3 levels) in start_threads`

To be honest, I'm not sure if this is an issue with Passenger, ActiveRecord or MySQL2. So I figured I'd start here. Thanks.

sodabrew commented 8 years ago

Do you have reconnect enabled? If not, then the effect of a mysql_ping on a dead connection will be raising an exception.

technopoetic commented 8 years ago

Yes, reconnect is enabled. My working hypothesis is that mysql_ping reconnects a dead connection and somehow that kills the current thread. When passenger sees the thread die, then it raises the ThreadHandler::Interrupted. I guess that makes the question, "What happens to the current thread when mysql_ping reconnects?"

And thanks for responding by the way.

sodabrew commented 8 years ago

A failure to reconnect should ultimately raise a Mysql2::Error rather than just terminating the thread. Is it possible you have contention on the connection, i.e. if the mysql_ping is called before the connection is actually checked out of the pool and locked by the thread?

technopoetic commented 8 years ago

I suppose it's possible. I'll have to look at it with an eye towards contention. I'm wondering about what happens when the reconnect succeeds. Passenger's request handler is where that exception comes from. mysql_ping is where we are when it happens, but this is the code that actually raises the exception:

def terminate_threads
  debug("Stopping all threads")
  threads = @threads_mutex.synchronize do
    @threads.dup
  end
  threads.each do |thr|
    thr.raise(ThreadHandler::Interrupted.new)
  end
  threads.each do |thr|
    thr.join
  end
  debug("All threads stopped")
end

And that gets called at the end of the main event loop, so it's almost like Passenger is starting a completely new process every time we get a reset connection.

I know that mysql_ping causes things to happen server side, like rolling back transactions, but does it cause anything to happen client side? Or should we just get a new connection and continue on our merry way?