Random slow Rack::MethodOverride#call on rails app on Heroku

Question

Environment:

• Ruby: 2.1.2

• Rails: 4.1.4

• Heroku

In our rails app hosted on Heroku, there are times that requests take a long time to execute. It is just 1% of times or less, but we cannot figure out what it is happening.

We have newrelic agent installed and it says that it is not request-queuing, it is the transaction itself who takes all that time to execute.

However, transaction trace shows this:

(this same request most of the times takes only 100ms to be executed)

As far as I can tell, the time is being consumed before our controller gets invoked. It is consumed on

Rack::MethodOverride#call

and that is what we cannot understand.

Also, most of the times (or even always, we are not sure) this happens on POST requests that are sent by mobile devices. Could this have something to do with a slow connection? (although POST-payload is very tiny).

Has anyone experienced this? Any advice on how to keep exploring this issue is appreciated.

Thanks in advance!

Shine

Answer 1

Since the Ruby agent began to instrument middleware in version 3.9.0.229, we've seen this question arise for some users. One possible cause of the longer timings is that Rack::MethodOverride needs to examine the request body on POST in order to determine whether the POST parameters contain a method override. It calls Rack::Request#POST, which ends up triggering a read that reads in the entire request body.

This may be why you see that more time than expected is being spent in this middleware. Looking more deeply into how the POST body relates to the time spent in the middleware might be a fruitful avenue for investigation.

Wagonette

Thank you very much for your quick answer! One more question if you also know it: at that point, request body is already on dyno's memory? or, reading request body may be affected by client's connection. I mean, if client's connection is slow, can that be the reason why it takes so much time to read the request body? – Shine

Answer 2

In case anyone is experiencing this:

Finally we have made the switch from unicorn to passenger and this issue has been resolved:

https://github.com/phusion/passenger-ruby-heroku-demo

I am not sure, but the problem may have something to do with POST requests on slow clients. Passenger/nginx says:

Request/response buffering - The included Nginx buffers requests and responses, thus protecting your app against slow clients (e.g. mobile devices on mobile networks) and improving performance.

So this may be the reason.

Shine

I solved this using nginx in front of our unicorn workers. We are on heroku, so I used this buildpack here: github.com/ryandotsmith/nginx-buildpack – Canova