rails 2 and slow external services

ghazel at gmail.com ghazel at gmail.com
Thu Dec 16 09:39:52 EST 2010


On Mon, Dec 13, 2010 at 10:35 PM, Eric Wong <normalperson at yhbt.net> wrote:
> ghazel at gmail.com wrote:
>> I'm running a bit of my traffic through some Rainbows! right now, but I got:
>>
>> 2010/12/14 02:30:24 [error] 3183#0: *9229917 upstream timed out (110:
>> Connection timed out) while reading response header from upstream,
>> client: 1.2.3.4, server: mysite.com, request: "GET /blah HTTP/1.1",
>> upstream: "http://unix:/tmp/rainbows.sock:/blah", host: "mysite.com",
>> referrer: "https://foofoo.com"
>> 2010/12/14 04:28:25 [error] 3182#0: *9440717 upstream timed out (110:
>> Connection timed out) while reading response header from upstream,
>> client: 5.6.7.8, server: mysite.com, request: "GET /blah HTTP/1.1",
>> upstream: "http://unix:/tmp/rainbows.sock:/blah", host: "mysite.com"
>>
>> From nginx in the error log. My proxy_read_timeout is 300, and my
>> listen backlog is 2048 (for now...). Basically my Rainbows! config is
>> identical to my Unicorn config, where I have not seen that happen,
>> except I added "Rainbows! { use :ThreadPool; worker_connections 100
>> }".
>
> Was your app hitting the Unicorn kill -9 timeout frequently before?  In
> Rainbows!, the kill -9 timeout only kicks in when the entire
> interpreter/VM is stuck due to a broken C extension or bug in Ruby.
>
> If it's some component of your app taking a long time (and relying on
> the Unicorn kill -9 timeout), you can try the Rainbows::ThreadTimeout
> middleware: http://rainbows.rubyforge.org/Rainbows/ThreadTimeout.html

I believe I found a bug in ThreadTimeout. It seems to be terminating a
request immediately every @timeout seconds. I'm using :ThreadSpawn and
my initializer is:
use Rainbows::ThreadTimeout, :timeout => 299

The observed behavior is that the request dies < 1 second later with
Rainbows::ThreadTimeout::ExecutionExpired. If I look 299 seconds back
in the log, I see another request killed prematurely. If I look 299
further back from that, I see the process started at this time.
Glancing at the code:

        now = Time.now
        @lock.synchronize do
          @active.delete_if do |thread, time|
            time >= now and thread.raise(ExecutionExpired).nil?
          end
        end

The "time >= now" seems incorrect to me. Since "time" is set to
"Time.now + @timeout" it will be greater than Time.now while the
request still has time left. I believe that should read "now >= time".

-Greg


More information about the rainbows-talk mailing list