Rails completes in 15 seconds, response received after 2 more minutes

Question

I'm running into an unusual situation that I can't get to the bottom of. We have a rails 4.1 application running on jRuby 1.7.12 inside Torquebox 3.1.0. One of the API endpoints retrieves a list of objects.

Currently the database has just under 7000 records in. When an API request is made, these are queried and rendered in JSON using the ActiveModel::Serializersgem. This all works as we'd expect, and doing this in a rails console, it works perfectly.

The problem lies when making an actual API request. It seems to work as expected, and looking at the rails log, there is the output

Completed 200 OK in 6354ms (Views: 5479.0ms | ActiveRecord: 867.0ms)

At this point, I expect to see the data returned from the server, however it takes a good 2.7 minutes to actually see a response from the server. I've tried making the request from Chrome, Safari and even in curl just to make sure it's not a weird browser issue but not having any luck.

I've implemented some caching within the serialisers as described here. I'm pretty sure this isn't the issue however as it works as expected in a console, so I'm really confused.

What else could be going on that is causing the 2+ minute delay. During this time I'm seeing around a 100% CPU usage for Java, so something is definitely going on.

Answer 1

Well it turns out it was the bullet gem taking up all the time. It seems that with that many records, detecting whether there is an N+1 query is quite time consuming. Simply disabling bullet reduces the time to exactly what the rails console says it is.