ActionDispatch::Routing::RouteSet#call Rails 4.1 really slow

Question

I've searched for days but can't find any relevant answers to this question.

In my Rails 4.1 app hosted on Heroku, when the load goes up, some PUT requests get REALLY slow. The slowest one today was 53 seconds. All without the database (MongoDB) registering any slow queries. Normally this request takes 0.3ms so pretty fast. The request is slow no matter what the payload is.

Upon installing New Relic it shed some more light on the situation, but I still don't know where to fix this problem.

The code in the controller is fast, but according to New Relic, the thing that is slow is ActionDispatch::Routing::RouteSet#call

Here's a dump of what New Relic reports:

Slowest components                      Count   Duration    %
ActionDispatch::Routing::RouteSet#call  1   53,000 ms   100%
Plugin::FetchablesController#update     1   38 ms       0%
Rails::Rack::Logger#call                1   1 ms        0%
ActionDispatch::Cookies#call            1   1 ms        0%
ActiveSupport::Cache::Strategy::LocalCache::Middleware#call 1   0 ms    0%
Rack::Runtime#call                      1   0 ms        0%
Total                                       53,000 ms   100%

Some other info that might help or could perhaps have something to do with this. I have an alias for the routes, but I can't see why that should matter.

namespace :plugin do
   resources :fetchables, path: :minables
end

Any ideas on what might be going on and what I could do to fix it would be greatly appreciated.

Update So it seems that this is memory related. When we upgraded to Performance Dynos we've stopped seeing these errors. But this is something that seems to be seriously badly configured at Heroku.

Gifferd

I am also facing the same issue. Did you find any solution? Which rails version are you using? – Lugo

Nope no solution yet. I've narrowed the problem down to that it happens when users do large updates. Especially if they are on a slow connection. Is rails perhaps spending its time in the RouteSet call when it is receiving the data for the parameters? I always thought it would be received as one big chunk in the finished request? – Gifferd

I faced such scenario with simple get calls. It didn't had big chunks of data in parameters. I suspect that it might be due to large env object which hold big sessions data. – Lugo

I'm having the same problem. Did anyone find any clues? – Robeson

Nothing yet. but I just switched to Puma on Heroku and I'm hoping that it might fix the issues, but haven't dug in or tested it yet. – Gifferd

Can you share some samples of the put requests that tend to be slow? – Dewyeyed

Please post an answer if you found one because I am experiencing this as well. – Okeefe

Hi, I still haven't been able to resolve this issue, but my way of dealing with it now will be to move away from Heroku and this is one of the major reasons – Gifferd

How many users / traffic are you getting? Have you done a load test on the app? – Bukharin

We ran into similar slow "ActionDispatch::Routing::RouteSet#call" too. In our case, it was not directly related specifically to this call, but it was an overall lack of memory on our machine. Due to a misconfigured Rack::Cache, Rails was allocating 3x more objects than normal. We found that out bij studying the "Ruby VM" behaviour in New Relic. – Dah

Thanks @PascalLindelauf I'm suspecting that it was a memory issue. Because now that I think of it, it hasn't occurred since we upgraded to the Performance Dynos which have a lot more memory. – Gifferd

What version of Ruby did you use? Did you use a non-MRI version? – Ricotta

Answer 1

The slowdown is an indicator that it's Heroku-specific. Probably why you saw the problem disappear when you upgraded to Performance Dynos.

Muna

Answer 2

You could use rack-mini-profiler to check where the real problem is.

Ermey