rails/rails — pull request #5423 by jrochkind (2012-03-13 22:37:12+00:00)
Title: ConnectionPool.checkout needs to be restructured to take account of ruby's "non-blocking" strategy for mutex ConditionVariables

sorry @tenderlove, you're going to hate me for this one, but at this point I've done some due dillegence and am reasonably confident I've found an actual issue -- which does affect my app -- having to do with some deep stuff regarding how ruby Monitor ConditionVariable's work. It requires some restructuring and slight uglification of the ConnectionPool.checkout method.

This is a tricky one. I have a test, but due to the race condition nature of the bug, it only sometimes fails, so I didn't include it it in the pull commit not sure if that was appropriate, but it's included below.

The problem occurs when you have a lot of threads (more than connection pool size) all wanting to checkout connections for very very short periods of time.

Conceptually, this ought to be accommodated no problem. Each thread only needs the connection for a very short period of time, orders of magnitude less than the timeout -- even if there's more of them then there are connections, they should each be able to take a turn, waiting when neccesary and all finishing long before timeout no problem.

In fact, _sometimes_ (race condition, so it appears in some runs and not others), some of these threads will end up raising a ConnectionTimeoutError --- **long before** the timeout value is reached. They appear to be giving up and not getting a connection in miliseconds, long before the 5 second time out.

Why? As far as I can tell, here's the deal.

* threadA wants a connection, but the pool is full, so it blocks on [`@queue.wait(@timeout)`](https://github.com/rails/rails/blob/3-2-stable/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L246)

* shortly thereafter, threadB checks in a connection, and does a [`@queue.signal`](https://github.com/rails/rails/blob/3-2-stable/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L270)

* this does wake up threadA, however threadA does not immediately get access to the mutex to be in it's 'synchronization' block. Some *other* thread slips into 'synchronization' first, checks out the newly avail conenction, and then at a later point threadA gets access to the mutex 'synchronization' block
** It [finds there are no connections available](https://github.com/rails/rails/blob/3-2-stable/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L248), assumes this means that it only woke up from `@queue.wait` because of a timeout, and throws the ConnectionTimeoutError . But the 5 seconds hadn't elapsed, hardly any time at all elapsed, it got woken up because there was a checkin, another thread just stole it first.

At first this seemed to be like it must be a bug in ruby Monitor/ConditionVariable itself, or else ConnectionPool somehow not synchronizing in enough places, or something.

However, reading up on how Monitors and ConditionVariables work, this seems like *one* accepted model for the way they work -- and appears to be how ruby works. The [wikipedia article on Monitors](http://en.wikipedia.org/wiki/Monitor_(synchronization)) refers to these two models as "blocking condition variables" and ["non-blocking condition variables"](http://en.wikipedia.org/wiki/Monitor_(synchronization)#Nonblocking_condition_variables)

This [article on Java](http://www.baptiste-wicht.com/2010/09/java-concurrency-part-5-monitors-locks-and-conditions/) refers to the two categories instead as "Signal & Continue" (non-blocking) and "Signal & Wait" (blocking), and says Java uses the "Signal & Continue" method:

> Signal & Continue (SC) : The process who signal keep the mutual exclusion and the signaled will be awaken but need to acquire the mutual exclusion before going.

That appears to be what ruby is doing too, although Monitor rdoc doesn't specify, and I wasn't able to understand the code enough to be sure -- that matches observed behavior here. So, the process which signals keeps the mutex, the signaled awakens but just gets added to the queue to aquire the mutex to operate in it's 'synchronized' block, and other threads may in front of it. Yep, that's happening.

Here's a test case which on my machine fails in about 80% of runs. Tested with both MRI 1.9.3-p0 and jruby 1.6.7 in 1.8.7 mode. That jruby has the same race condition is not surprising based on info that Java also uses the non-blocking/Signal-and-continue approach.

def test_wait_on_connection
main_connections = []

# Fill er up
(pool.spec.config[:pool] || 5).times do
main_connections << pool.checkout
end

threads = []
10.times do
threads << Thread.new do
pool.with_connection do |conn|
assert conn
sleep 0.01
end
end
end

pool.checkin main_connections.shift

assert_nothing_raised do
threads.each {|t| t.join}
end

main_connections.each {|c| pool.checkin c}

end

Without the included pull request, test fails due to race condition approximately 80% of runs on my machine, may differ on yours. (adding more runs to the `10 times` may make it more likely to fail) Note that if you run just this test by itself, on failure run, it completes with failure in _way_ less than the 5 second timeout, even though it reports a failure due to ConnectionTimeoutError "could not get connection in 5 seconds."

With the included pull request, I was not able to get the test to fail in a bunch of runs -- and additionally my much more complex app no longer exhibited the problematic behavior I was seeing, where it raised ConnectionTimeoutError's when I didn't see any reason why, unless given a larger connection pool than seemed like should be neccesary.

The restructure in the pull request changes the order of operations in the loop in `#checkout`, but it also has to do some ugly things with keeping track itself of how long it slept during the `@queue.wait`. I couldn't think of any other way for it to determine whether the timeout was really up, in cases where it returned from `@queue.wait` with a connection still unavailable. It may execute multiple `@queue.wait`s in successive loop iterations. The total of all of them should be no more than _approximately_ the timeout value, as it keeps a running count of waiting time. This is neccessarily not _exactly_ the @timeout value because there's really no way to get that exact measure, but it'll be pretty close, and should be good enough for what @timeout is meant to accomplish.

Not sure if there's an existing test that asserts that when a thread really _can't_ get a connection it does raise ConnectionTimeout, and in about 5 seconds -- but I verified myself this was still true post-commit. (such a test would take 5 seconds to complete, which would be annoying, unless perhaps using a pool with a much smaller timeout).

This is against 3-2-stable, as was all my work. Likely needs to be done in master too.

Phew. Hope I explained this clearly using no more words than needed, although it took a lot of words.