Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

mysql_ping causing Thread interrupts in Phusion passenger #777

Open
technopoetic opened this issue Jul 14, 2016 · 4 comments
Open

mysql_ping causing Thread interrupts in Phusion passenger #777

technopoetic opened this issue Jul 14, 2016 · 4 comments

Comments

@technopoetic
Copy link

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
Copy link
Collaborator

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

@technopoetic
Copy link
Author

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
Copy link
Collaborator

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
Copy link
Author

technopoetic commented Jul 14, 2016 •
edited
Loading

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sodabrew @technopoetic