#1927 Connection pool timeout in production mode with AR sessions - Ruby on Rails

Type	To find
responsible:me	tickets assigned to you
tagged:"@high"	tickets tagged @high
milestone:next	tickets in the upcoming milestone
state:invalid	tickets with the state invalid
created:"last week"	tickets created last week
sort:number, importance, updated	tickets sorted by #, importance or updated
Combine keywords for powerful searching.
Use advanced searching »

This project is archived and is in readonly mode.

#1927 ✓resolved

Connection pool timeout in production mode with AR sessions

Reported by Peter Nash | February 10th, 2009 @ 10:07 AM

It would appear that in Production mode with ActiveRecord session store enabled there is a timeout (default 5 seconds) when the connection pool is full when using MySQL.

To reproduce:

Create a trivial rails app with 2.3RC1 with ActionController::Base.session_store = :active_record_store (I'm using a trivial, scaffold generated model/controller)

Run the app in production mode, create a record in the database and then, in the browser, hit "refresh" on the index action of the controller at 1 second intervals. Every 4-5 refreshes the browser will "stall" for 5 seconds although the log output shows no addtional time in the "View:" or "DB:" entries in the log (see below).

Increasing the size of "pool" in database.yml delays the onset of the problem.

Changing "timeout" from it's default of 5000 in database.yml appears to have no effect.

However, adding an entry for "wait_timeout" to database.yml and reducing it's default value(5) to 1 or 0.5 changes the "stall" time in the browser to 1 or 0.5 seconds.

The problem is not apparent in development mode (I believe the connection pool is cleared for each request).

The problem is not apparent if AR session store is disabled.

Monitoring the connections in MySQL Admin I can see that the number of open connections increases with each request until it reaches the value of "pool" at which point the problem starts - I assume that connections are not being closed at the end of each request.

Environment:

Server: MySQL server 5.0.45 on a networked RedHat Linux server (not localhost)

Client 1: CentOS 5.2, MySQL 5.0.45, mysql gem 2.7.3

Client 2: Windows Vista, MySQL 5.0.67, mysql gem 2.7.3

Identical results on both clients.

I have not tried to reproduce the problem with any other database adapter.

Sample log output from hitting "refresh" in the browser aprrox. 1 second after each page reload - note the 5+ second delay between the last an penultimate request:

Processing MoviesController#index (for 127.0.0.1 at 2009-02-10 10:02:58) [GET] Rendering template within layouts/movies Rendering movies/index Completed in 7ms (View: 2, DB: 6) | 200 OK [http://localhost/movies]

Processing MoviesController#index (for 127.0.0.1 at 2009-02-10 10:02:59) [GET] Rendering template within layouts/movies Rendering movies/index Completed in 7ms (View: 4, DB: 5) | 200 OK [http://localhost/movies]

Processing MoviesController#index (for 127.0.0.1 at 2009-02-10 10:03:01) [GET] Rendering template within layouts/movies Rendering movies/index Completed in 6ms (View: 3, DB: 10) | 200 OK [http://localhost/movies]

Processing MoviesController#index (for 127.0.0.1 at 2009-02-10 10:03:02) [GET] Rendering template within layouts/movies Rendering movies/index Completed in 8ms (View: 3, DB: 9) | 200 OK [http://localhost/movies]

Processing MoviesController#index (for 127.0.0.1 at 2009-02-10 10:03:03) [GET] Rendering template within layouts/movies Rendering movies/index Completed in 5ms (View: 2, DB: 52) | 200 OK [http://localhost/movies]

Processing MoviesController#index (for 127.0.0.1 at 2009-02-10 10:03:09) [GET] Rendering template within layouts/movies Rendering movies/index Completed in 6ms (View: 2, DB: 9) | 200 OK [http://localhost/movies]

Comments and changes to this ticket

You flagged this item as spam.
Zach Holman February 23rd, 2009 @ 07:24 PM
I can confirm this on our pre-2.3RC1 app that's now running RC1. Pretty difficult to track down, given all of our logs show normal response times as Peter indicated. We were seeing this both on Ubuntu and on OS X.

Seems like it could pose a pretty significant problem; we've moved onto a different session store in the meantime, but given the somewhat common MySQL+ActiveRecordStore combo and how opaque it is to the developer, it might be worth taking a closer look at.
josh February 23rd, 2009 @ 08:06 PM
- Assigned user set to “josh”
- Milestone cleared.
You flagged this item as spam.
Brendan Schwartz February 24th, 2009 @ 03:30 PM
For what it's worth, I observe this connection pool timeout behavior when running requests through mongrel (1.1.5) but everything appears to be fine when using thin (1.0.0).
Repository February 24th, 2009 @ 05:34 PM
- State changed from “new” to “resolved”
(from [1b22071b276a2a2b3e65e6db40c6a0aa92d9ebc3]) Ensure ActiveRecord session store's connections are checked in after each request [#1927 state:resolved] http://github.com/rails/rails/co...
You flagged this item as spam.
Peter Nash February 25th, 2009 @ 03:48 PM
Thanks - that's fixed it.
You flagged this item as spam.
Ryan Angilly April 3rd, 2009 @ 11:52 PM
- Tag changed from “2.3” to “2.3, performance, rack”
Hey is anyone else seeing this again? We were seeing a problem like this on our staging server for the past month (after upgrading to 2.3), but figured it might have just been our crappy staging server. We just pushed live to a much more powerful slice, and sure enough every 20-30 seconds we see requests take 4.8 - 5.3 seconds to return in curl.

Josh, could you give some insight into what this problem actually was, and how you believed you were fixing it when you committed the patch?

Thanks guys, Ryan
You flagged this item as spam.
Peter Nash April 4th, 2009 @ 03:55 PM
Hi Ryan

I'm not seeing the problem the the 2.3.2 gem version of Rails. I've tested against the two apps where I originally saw this in production mode and all looks fine. I've not tested against Edge.

Peter.
You flagged this item as spam.
Peter Nash April 4th, 2009 @ 03:57 PM
.... that should have been "with the 2.3.2" .....
You flagged this item as spam.
Ryan Angilly April 4th, 2009 @ 05:37 PM
Yeah turns out we were using sql_session_store (it's a really old app) instead of active_record_store. We put AR store up on our staging slice and things seems to be behaving properly now.

Thanks for posting such a detailed description originally. The wait_timeout set to 0.5 hack gave us just enough time to figure things out.