AR adapter connection pool management problem #31

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

Projects

None yet
@wvanbergen
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).

Owner

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

Contributor

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 ...
Contributor

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.

Contributor

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.

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.

Contributor

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

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..

Contributor

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.

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?

Owner

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

Contributor

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 :-)

Owner

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

Cool !
Keep us posted !

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

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.

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

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?

Contributor

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!

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 !

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!

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 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.

Owner

What version of rails and ruby?

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...

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

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 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

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.

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 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 :-)

Contributor

I was having issues with Webrick, and my colleague with mongrel. In production mode, on Passenger, all works fine. Now I am using Rails 3RC and Mysql2 HEAD, I am also able to run my app without problems.

gucki commented Jul 28, 2010

Didn't have any errors (mysql closed, mysql lost) for around 16 hours now.. :-)

Owner

Holy crap I think we may have found it... Will push once I understand why it fixed it :)

Contributor

I am hopeful. The errors starting appearing again with Mysql2 master and Rails3RC.

Another note: I am always getting the error when the query is done from a helper method, during template rendering. Don't know if that actually means anything :-)

Owner

Yeah the issue is actually kinda tricky... That's why it's been so hard to track down, because it's seemingly random - which lead me to think it was related to the GC. I've been able to reproduce the error locally for a while, and after I put this fix in I haven't been able to since. Hopefully that's a good sign :)

dvdplm commented Jul 28, 2010

Installing from master works for me. Awesome! :)

Owner

Ok everyone, just pushed dd138de with the fix. Want to give it a go?

gucki commented Jul 28, 2010

I think you latest patch will not work. In fact it should crash ruby, because you are accessing a member of a structure deallocated/freed by mysql_close.

http://dev.mysql.com/doc/refman/5.1/en/mysql-close.html

Closes a previously opened connection. mysql_close() also deallocates the connection handle pointed to by mysql if the handle was allocated automatically by mysql_init() or mysql_connect().

As pointed out before, mysql2 works perfectly fine after removing the MACRO for me for 24+ hours now. Did anybody else try my patch?

gucki commented Jul 28, 2010

Ok, it might work because I saw you allocate the structure yourself and so mysql_close should not free it. I'll give your patch a try tommorrow :-)

nragaz commented Jul 29, 2010

Brian, I have not seen this error after ~12 hours using master. Cautiously optimistic! Than you.

Owner

Awesome! Thanks for the update. I'd like to get this issue closed, can anyone else attest to the fix?

Owner

Closing for now, this fix will be in 0.2.0

kjvarga commented Jul 31, 2010

So far so good with your latest patch @brianmario. Interestingly enough I was previously only getting this using mysql2 and Ruby 1.8.7, but then yesterday I started getting it out of the blue on Ruby 1.9.2-head. With your patch the problem hasn't recurred yet.

+1, waiting for 0.2.0 to see if it helps.

Ruby 1.8.7 p249
MySQL 5.1.41
Passenger 2.2.15
Ubuntu Jaunty

Thanks!,
James

tobsch commented Aug 9, 2010

I've seen this error with a current snapshot of master :-(
Anything I could help with?

Owner

Yeah... I think we have a much better idea of what's going on now. Will try and push a real fix soon. Need to do some experiments, threading is hard :(

Owner

Basically, we're allocating the MYSQL* struct ourselves in the allocate() function in client.c - typically mysql_init() handles that for us. Since we're doing it ourselves, we also need to free it ourselves. I think that's where the issue is. Gonna try a refactor to let libmysql do all the allocation/freeing internally again.
Will post my progress...

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 :/ )

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 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'

Owner

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

iain commented Aug 16, 2010

Seems to work fine!

Owner

NICE thanks for testing man

Owner

0.2.0 pushed

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 commented Aug 27, 2010

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

Owner

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

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?

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 commented Aug 30, 2010

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

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'
    ...
Owner

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

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!

Owner

Forgot to ask which version of ruby?

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
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 commented Sep 17, 2010

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

Owner

bad. ass.

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 commented Sep 23, 2010

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

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 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 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.

Owner

Could you guys give master a try?

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 commented Oct 15, 2010

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

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