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.

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

AR adapter connection pool management problem #31

Closed
wvanbergen opened this issue Jul 20, 2010 · 77 comments
Closed

AR adapter connection pool management problem #31

wvanbergen opened this issue Jul 20, 2010 · 77 comments
Labels

Comments

@wvanbergen
Copy link
Contributor

I am having troubles with the connection management of the ActiveRecord adapter. For some reason, I am getting "Mysql2::Error: closed MySQL connection" after a couple of refreshes of the same page.

The page uses one ActiveRecord.find(id) call, and several (about 10) calls to the ActiveRecord::Base.connection.select_values(sql) method. It usually works fine the first time and after the first and second refresh of the page, but it'll fail eventually.

The error occurs outside of my own code. This is the backtrace:

mysql2 (0.1.9) lib/active_record/connection_adapters/mysql2_adapter.rb:246:in `close'
mysql2 (0.1.9) lib/active_record/connection_adapters/mysql2_adapter.rb:246:in `disconnect!'
activerecord (3.0.0.beta4) lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `clear_reloadable_connections_without_synchronization!'
activerecord (3.0.0.beta4) lib/active_record/connection_adapters/abstract/connection_pool.rb:144:in `each'
activerecord (3.0.0.beta4) lib/active_record/connection_adapters/abstract/connection_pool.rb:144:in `clear_reloadable_connections_without_synchronization!'
activesupport (3.0.0.beta4) lib/active_support/core_ext/module/synchronization.rb:34:in `clear_reloadable_connections!'
/Users/willem/.rvm/rubies/ruby-1.8.7-p174/lib/ruby/1.8/monitor.rb:242:in `synchronize'
activesupport (3.0.0.beta4) lib/active_support/core_ext/module/synchronization.rb:33:in `clear_reloadable_connections!'

When I comment out the calls to the custom select_values call, the problem does not seem to occur anymore. This is the code I am using:

  sql = <<-EOSQL 
        SELECT DISTINCT #{field} AS `possible_value`
          FROM `#{table_name}` 
         ORDER BY `possible_value`
      EOSQL

  ActiveRecord::Base.connection.select_values(sql)

These errors only occur in development mode; in production everything seems to be working OK. Also, when I rewrite the method above to use execute and handle the result myself, the problem persists. Moreover, the exact same code works fine with the normal mysql gem, except for some typecasting issues (which is why I want to use mysql2).

@brianmario
Copy link
Owner

Would you mind trying again from master?
I pushed a fix here: http://github.com/brianmario/mysql2/commit/9ab1c90d2b669e7527215793c3a2bba56c7f48a8

@wvanbergen
Copy link
Contributor Author

It is still failing, but now it actually raises the error on the select_values call I described:

Mysql2::Error: closed MySQL connection: SELECT DISTINCT ...

@wvanbergen
Copy link
Contributor Author

Moreover, the error is not persistent anymore. Previously, when the error occurred, I had to restart the server. Now, I can just refresh and it sometimes is successfully able to serve the request again, but not always. Weird.

@wvanbergen
Copy link
Contributor Author

Maybe this is also relevant: I am using multiple databases from database.yml. The initial AR.find is done on the development database, and the custom queries are done on another connection. Both are using mysql2.

@fmalamitsas
Copy link

If it can help Brian, I have the same issue, but I have only one database.
As for me I always have to reboot my server.

@wvanbergen
Copy link
Contributor Author

I am trying to create a minimal sample app that recreates the problem, but so far, I have not been successful.

@fmalamitsas
Copy link

It seems to be something external.
I've been using mysql2 for more than a month now, and this bug appeared 2 days ago.
but I can't find what is causing this..

@wvanbergen
Copy link
Contributor Author

For now, I have worked around the problem by using the MySQL2 API directly for the custom query I am using. This means I am using a lot more connections, but at least it is working reliably now. This does seem to indicate that the problem is in the AR adapter.

@brianmario
Copy link
Owner

I pushed 0.1.9 on the 17th, could you give 0.1.8 a try and see if you have the same issue?

@brianmario
Copy link
Owner

Pretty sure I tracked down the issue, could you give master another try?

@wvanbergen
Copy link
Contributor Author

Seems to be working fine for me now. Thanks!

It's amazing that you are able to track down an issue with a vague description like this :-)

@brianmario
Copy link
Owner

I actually decided to revert that commit, and will try and track down the issue in the AR adapter... hold tight!

@fmalamitsas
Copy link

Cool !
Keep us posted !

@kjvarga
Copy link

kjvarga commented Jul 22, 2010

+1 here...also started just in the last couple days, but we have had a lot of development happen so no one knows exactly what changed. We are using Bundler with Rails 2.3.8. A few devs are experiencing this consistently, including myself.

Thanks for checking it out Brian

@brianmario
Copy link
Owner

Hey guys,
If you're using Bundler you could point directly at commit 70a7298 which is the fix I later reverted and seemed to solve the issue for @wvanbergen.
Still looking into the issue on my side, should hopefully have something to push in the next couple/few days.

@fmalamitsas
Copy link

Hi Brian,

the problem with this ref. is that we might get some random errors while running the app.
A temporary "fix" that works with the last revision is to set cache_classes variable to true in the development.rb file and there is no more errors.

Thanks Brian for this gem

@brianmario
Copy link
Owner

Ok guys,
was finally able to create a reproducible case locally in a 2.3 app. Apparently the "requires_reloading?" method returns true in the AbstractAdapter class in 2.3, but false in 3.0 (which is why I wasn't seeing an issue in 3.0).
It appears that the sqlite3 adapter is the only one that actually needs that method to return true, so I've overridden it to forcefully return false for the mysql2 adapter.
That seemed to fix the problem for me. Would you guys mind giving master another try?

@wvanbergen
Copy link
Contributor Author

I am also using a Rails 3 application so it wasn't Rails 2.3 specific. That said, this change seems to solve the problem for me. Thanks!

@fmalamitsas
Copy link

Hi Brian,
unfortunately I'm not able to test your fix now, but I'm using rails3 as well.

Hope it'll work ! Many thanks again !

@brianmario
Copy link
Owner

Ah, this may have been a recent fix (post beta4) to AR in rails3. I'll double check on that and wait for one more of you to have a chance to test it before closing the ticket. Thanks for your help in tracking it down guys!

@brianmario
Copy link
Owner

Looks like it was fixed/changed (again?) in Rails3 in this commit: http://github.com/rails/rails/commit/62c4e4d3856b38ee9869f4ad6342e712788c8635
14 days after beta4 was cut.

@nragaz
Copy link

nragaz commented Jul 25, 2010

I'm still seeing this error on your master. Let me know if there is other info I can provide.

It's highly intermittent, though, so hard to reproduce.

@brianmario
Copy link
Owner

What version of rails and ruby?

@nragaz
Copy link

nragaz commented Jul 25, 2010

Ruby Enterprise Edition 2010.02 and Rails 3 (master). I also wonder if this error has something to do with serving via Unicorn...

@fmalamitsas
Copy link

Hi Brian,
it's seems to work well now !
Many thanks for your reactivity !

@gucki
Copy link

gucki commented Jul 27, 2010

I'm having the same error using rails3.rc, latest unicorn and latest mysql2 gem. The error only occurs if you set "preload_app true". My unicorn is configured correctly with:

before_fork do |server, worker|
  ActiveRecord::Base.connection.disconnect!
end

after_fork do |server, worker|
  ActiveRecord::Base.establish_connection
end

I also tried the latest snapshot from github for mysql2, but the error still occurs. The only workaround for now it to set "preload_app false".

@gucki
Copy link

gucki commented Jul 27, 2010

After some debugging it seems the error is inside the mysql2_ext.h file.

The macro REQUIRE_OPEN_DB check some internal field of the MYSQL structure and assumes the connection is closed if the net.vio field is NULL. But this seems to be a wrong assumption. Even thought net.vio is NULL sometimes, the connection is still alive and working perfectly.

I'd suggest simply removing this macro completely (it works fine for me then). If the connection is closed the mysql functions won't crash, they'll return an error anyway. And I think it's not a good practice to work with any internal fields (at least I think it's an internal field because I couldn't find any documentation on it).

If you want to give it a try, please try my fork. Please let me know how it works :-)

http://github.com/gucki/mysql2/commit/15932686254749f2a66962a1565b0637a61d1364

@brianmario
Copy link
Owner

I actually tried this recently and was still getting errors. They were just coming from libmysql instead of the ruby extension itself. They were the typical "MySQL server has gone away..." error I'm sure we've all seen many times.

I suspect the issue is something to do with the AR driver telling the connection poll the wrong thing... Still trying to track it down.

@brianmario
Copy link
Owner

I'm able to reproduce this using Unicorn, although I can't with thin/webrick/mongrel. I can also reproduce it with "preload_app false" - something is definitely up with the combination of AR's connection pool and mysql2's AR adapter.
Will post as I make progress.

@gucki
Copy link

gucki commented Jul 27, 2010

I'm running my app with the patched mysql2 for some time now and didn't have any problems so far. Without the patch I got the errors just after a few seconds.
I also got the errors when using DelayedJob. With the patch DelayedJob is running fine too.
If I hit the bug again (with the patch) I'm going to investigate further too :-)

@tomash
Copy link

tomash commented Aug 11, 2010

stumbled upon same bug here, rails 3 rc on ruby 1.9.2.
waiting eagerly for 0.2.0 -- our app hasn't gone production yet, but restarting staging app is pretty frustrating. good luck with hunting that heisenbug! (I wish I had some knowledge of libmysql so I could help :/ )

@brianmario
Copy link
Owner

For now you can point to the Rails repos 3-0-stable branch and also mysql2's master branch in your Gemfile. The next RC of Rails is due any day now and I'll be pushing 0.2.0 very soon as well.

@iain
Copy link

iain commented Aug 16, 2010

confirming that using the edge versions works.

  • Using unicorn with 4 workers and preload_app true

  • Latest REE on latest stable Ubuntu

  • This gemfile:

    gem 'rails', :git => 'git://github.com/rails/rails.git', :branch => '3-0-stable'
    gem 'mysql2', :git => 'git://github.com/brianmario/mysql2.git'

@brianmario
Copy link
Owner

Awesome! Thanks for testing that out
Would you mind giving it another try with my latest commit? cebf9af

@iain
Copy link

iain commented Aug 16, 2010

Seems to work fine!

@brianmario
Copy link
Owner

NICE thanks for testing man

@brianmario
Copy link
Owner

0.2.0 pushed

@tomash
Copy link

tomash commented Aug 23, 2010

still have been running onto this issue with 0.2.0 and 0.2.1

now giving 0.2.3 a try. as for now it's been running smoothly for a few hours now.

@tomash
Copy link

tomash commented Aug 27, 2010

still the same with mysql2 in 0.2.3 version :(
the server used in production is Thin

@brianmario
Copy link
Owner

Could you give me a snippet to reproduce? Also, what other details: ruby version and architecture, operating system, rails/sinatra, etc

@tomash
Copy link

tomash commented Aug 27, 2010

No snippet to be shown -- it's just that after some hours application throws a 500 with "Mysql2::Error: closed MySQL connection" in production.log

System is Gentoo Linux
Rails 3.0.0.rc, Ruby 1.9.2-head (rvm), MySQL version 5.0.90
Rails app ran under Thin

Maybe I could provide you with some system/mysql logs? Which ones?

@brianmario
Copy link
Owner

Could you give Rails3 RC2 a try?
The problem you're having sounds related to this ticket on Rails: https://rails.lighthouseapp.com/projects/8994/tickets/5242-activerecordstatementinvalid-mysqlerror-mysql-server-has-gone-away

Which I'm pretty sure was fixed in RC2.
Note that the error message in that ticket is "mysql server has gone away" - the reason why you get "closed MySQL connection" from Mysql2 instead is because we do the connection checking in Mysql2 itself so that message is from Mysql2 - but it's essentially the same error.

@tomash
Copy link

tomash commented Aug 30, 2010

OK, I gave Rails3 final a try with mysql2 latest version. Let's see how it goes :)

@johnbarratt
Copy link

I'm seeing similar issues sparodically in backend scripts with latest master version, Merb 1.0.1, activerecord 2.3.8. These are for constantly used connections, and no threading. Example tracebacks with different messages :

./vendor/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract_adapter.rb:221:in `log': Errno::EBADF: Bad file descriptor: SELECT * FROM `static_locations` WHERE latitude = 24.43359375  and longitude = 54.31640625  ORDER BY weighting desc LIMIT 1 (ActiveRecord::StatementInvalid)
        from ./vendor/gems/gems/mysql2-0.2.3/lib/active_record/connection_adapters/mysql2_adapter.rb:314:in `execute'
        from ./vendor/gems/gems/mysql2-0.2.3/lib/active_record/connection_adapters/mysql2_adapter.rb:627:in `select'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in `select_all_without_query_cache'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract/query_cache.rb:62:in `select_all'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:664:in `find_by_sql'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:1578:in `find_every'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:1535:in `find_initial'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:616:in `find'
    ...

./vendor/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract_adapter.rb:221:in `log': Mysql2::Error: This connection is still waiting for a result, try again once you have the result: SELECT * FROM `static_locations` WHERE latitude = 29.8828125 and longitude = 29.970703125 (ActiveRecord::StatementInvalid)
        from ./vendor/gems/gems/mysql2-0.2.3/lib/active_record/connection_adapters/mysql2_adapter.rb:314:in `execute'
        from ./vendor/gems/gems/mysql2-0.2.3/lib/active_record/connection_adapters/mysql2_adapter.rb:627:in `select'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in `select_all_without_query_cache'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract/query_cache.rb:62:in `select_all'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:664:in `find_by_sql'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:1578:in `find_every'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:1535:in `find_initial'
        from ./vendor/gems/gems/activerecord-2.3.8/lib/active_record/base.rb:616:in `find'
    ...

@brianmario
Copy link
Owner

afaik Merb uses EventMachine which could be attempting concurrency in your app. Which mysql driver were you using before?

@johnbarratt
Copy link

I was using the old 'mysql' driver previously, v 2.8.1 with no problem. I'm not sure what concurrency might be being attempted in these. Originally we did have some concurrency issues with the backend scripts, & in fact was solved by loading the environment explicitly, and not using the concurrent setup you get running offline scripts normally with Merb.

Some other notes. There haven't been any of these errors reported from the webserver which is running through nginx+passenger. The problem happens randomly (at most every hours hour for an individual script), and occurs much more frequently during peak usage periods for the database, and the machines the scripts are running.

Thanks for your help!

@brianmario
Copy link
Owner

Forgot to ask which version of ruby?

@johnbarratt
Copy link

Sorry, I should have provided in the first place! Its using Ruby Enterprise Edition :

ruby 1.8.7 (2009-12-24 patchlevel 248) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2010.01

@brianmario
Copy link
Owner

A recent patch fixed a long standing bug that was probably the culprit of all of the strange hard to reproduce (for me) bugs people have been seeing. If any of you are still having issues would you mind giving master a try?

@nragaz
Copy link

nragaz commented Sep 17, 2010

FWIW, I am still not seeing these issues return with the latest HEAD.

@brianmario
Copy link
Owner

bad. ass.

@cyrille
Copy link

cyrille commented Sep 23, 2010

Hi Mario, I've lot of Mysql2::Error: closed MySQL connection errors with latest gem (0.2.4) on a production env with rails 3 and ruby 1.9.2
I'm willing to provide an hoptoad access if your are interested.
I've also tried to add those options in database.yml with no more sucess

reconnect: true
pool: 10
wait_timeout: 86400

@cyrille
Copy link

cyrille commented Sep 23, 2010

forgot mysql is a AWS RDS instance (so 5.1 version)

@varyform
Copy link

varyform commented Oct 2, 2010

Same error here: 0.2.4
http://pastie.org/1195131

upd: no such problem on staging server (same config)
upd2: reproduced on staging too
i was using version 0.2.1 on staging for 2 months or so w/o any issues

@fwalch
Copy link

fwalch commented Oct 11, 2010

Also have this error with 0.2.4. Downgraded to 0.2.3, error disappeared. I'm using REE and Rails 3.

@ehohn
Copy link

ehohn commented Oct 13, 2010

I have the same error with 0.2.4 when using multiple databases.
Stacktrace is here: http://gist.github.com/623727

Used Ruby 1.9.2 via RVM and Rails 3. Will downgrade to 0.2.3.

@brianmario
Copy link
Owner

Could you guys give master a try?

@ehohn
Copy link

ehohn commented Oct 14, 2010

Tried out master, and I cannot reproduce the error in rails console anymore. Until now it looks good to me. BTW, thanks for this awesome gem!

@fwalch
Copy link

fwalch commented Oct 15, 2010

Tried out master, and it seems to work. Thanks!

@ckoehler
Copy link

I have the same issue with Mysql2::Error closed MySQL connection on a custom Ruby-only app with EM with latest Ruby 1.9.1. I will give master a try as well.
EDIT: Didn't fix it, but since I found a workaround in my code and don't trust that it wasn't my bug to begin with, I guess you're off the hook :)

This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests