A slow postgres query on Heroku is not being interrupted by rack-timeout

Question

I haven't had much luck finding info via google, maybe someone here has had a similar issue.

We have a rails app running on Heroku with a Postgres DB. We have a particularly slow query (yes, we're working on fixing the query), but in the course of debugging this problem, I observed that our rack-timeout gem is not killing the request at 15 seconds. I've done a side-test via inserting a sleep(50) and sure enough, rack-timeout is working correctly in that case.

Here is a redacted copy of our logs showing that rack-time (time's up!) is happening minutes later and we're still seeing the H12 Request Timeout after 30 seconds.

    2011-12-14T21:15:16+00:00 app[web.2]: Started GET "/search?utf8=%E2%9C%93&terms=foo" for 173.164.186.205 at Wed Dec 14 13:15:16 -0800 2011
    2011-12-14T21:15:16+00:00 app[web.2]: search query elapsed time => [0.000365018844604492]
    2011-12-14T21:15:46+00:00 heroku[router]: Error H12 (Request timeout) -> GET /search dyno=web.2 queue= wait= service=30000ms status=503 bytes=0
    2011-12-14T21:18:47+00:00 app[postgres]: [6-1] [removed] [COBALT] LOG:  duration: 211241.725 ms  statement: SELECT  [truncated]
    2011-12-14T21:18:47+00:00 app[web.2]: 
    2011-12-14T21:18:47+00:00 app[web.2]: ActionView::Template::Error (Timeout::Error: time's up!: SELECT  [truncated]):

Any insight into why and how to enforce the rack-timeout?

Answer 1

Yes, what's happening here is what I call a zombie dyno. The 30 second timeout is ocurring in the routing mesh which sits above your Dyno. In theory, your dyno can run for hours, but the user will see an error after 30 seconds directly from the routing mesh.

So. what's happening is this:

1. Your request is made at 21:15:16
2. At 21:15:46 the routing mesh returns it's error, but your dyno is still processing
3. At 21:18:47 your request finishes.

As for whats happening with Rack::Timeout and your long running query, it maybe down to the pg gem your using as Rack::Timeout is reliant on threads to function correctly. This explains why you get the timeout the moment the database returns.

More info on zombie dynos: http://neilmiddleton.com/avoiding-zombie-dynos-with-heroku/