Why ActionDispatch::Routing::RouteSet takes so long

Question

I am using Grape on top of Rails 4.2.1 to provide API for our application.

But when I check Newrelic for performance today I found that RackApp Proc#call and Grape API::Root#call are taking up large amount of time. (See the screenshot)

Then I tried to log the time consumed in middleware with rack_timer and found that ActionDispatch::Routing::RouteSet is taking up most of the time:

Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 67.12579727172852 ms
Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 101.51457786560059 ms
Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 84.18059349060059 ms
Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 1236.2565994262695 ms
Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 8.124351501464844 ms
Rack Timer (Application Action) -- ActionDispatch::Routing::RouteSet: 55.65309524536133 ms

There are even cases that take 500ms - 1000ms in ActionDispatch::Routing::RouteSet. How could I track down this problem and how could I know what have I done wrong in Rails routes?

Thanks a lot for the help.

Oceanography

I have same issue, have you found the cause ? – Rhizomorphous

Answer 1

For me, it turns out that Newrelic ruby agent does't work with rocket_pants, the gem I use to build API endpoints.

There is a third party gem 'rocket_pants-rpm' to solve this issue, but the original one stop working from newrelic_rpm version 3.9+, to fix the issue, try using the forked version at https://github.com/SpartaSales/rocket_pants-rpm

This is how newrelic report looks for me after adding this gem.

newrelic request time percentage

Rhizomorphous