Hunting Down a Slow Rails Request

Recently, we started using Skylight opens a new window in production for one of our clients’ Rails applications, in an attempt to try to improve the performance of some of the more critical API endpoints.

Skylight reports on:

  • Time taken per request
  • Breakdown of time taken per SQL query
  • Object allocations per request

I noticed an unusually large amount of allocated objects for one request:

Skylight report

This request would take anywhere from 400ms to 3000ms to respond, which is WAY too long.

To debug this, I first captured the String object allocation count locally to see how it behaved:

Started GET "/email_accounts.json?results_per_page=30" for 127.0.0.1 at 2016-03-02 13:04:22 +0000
Processing by EmailAccountsController#index as JSON
  Parameters: {"results_per_page"=>"30"}

[[String, 150299], [Arel::Nodes::SqlLiteral, 5], [Arel::Nodes::BindParam, 4], [ActiveSupport::StringInquirer, 1]]
### JSON rendering happens here ###
[[String, 707982], [ActiveSupport::JSON::Encoding::JSONGemEncoder::EscapedString, 2922], [Arel::Nodes::SqlLiteral, 6], [ActiveSupport::StringInquirer, 1]]

Completed 200 OK in 5860ms (Views: 11.8ms | ActiveRecord: 564.9ms)

To get the amount of allocated strings, I used the following snippet:

strings = {}
ObjectSpace.each_object(String) { |str| strings[str.class] += 1 }
pp strings

As you can see, there are 700k+ allocated strings. It is very likely that this increase in object allocation is the culprit for the slow performance.

I dug a bit into the EmailAccount model and its associations, and noticed that this model had a one-to-many association. Supposedly, we were only returning one record for this association by using:

scope.includes(:latest_sync)

and

has_one :latest_sync, -> { order "email_account_syncs.last_attempt_at desc" },
                      class_name: "EmailAccountSync"

As it turns out, the has_one :latest_sync relationship was not being respected by the query performed in the index action, and thus:

EmailAccountSync Load (21.9ms)  SELECT "email_account_syncs".* FROM "email_account_syncs"  WHERE "email_account_syncs"."email_account_id" IN (24, 23, 22, 21, 20, 19, 18, 17, 16, 15)  ORDER BY email_account_syncs.last_attempt_at desc

This meant that all EmailAccountSync instances were getting loaded for each EmailAccount record. The limit that should have been in the SQL statement was not there.

I googled for a bit and found this issue opens a new window , which suggests using eager_load instead of includes, which fixes the issue.

The downside is that it introduces an N+1 query problem, but it’s a dramatical performance gain:

Started GET "/email_accounts.json?results_per_page=30" for 186.158.142.200 at 2016-03-02 13:41:44 +0000
Processing by EmailAccountsController#index as JSON
  Parameters: {"results_per_page"=>"30"}

[[String, 150295], [ActiveSupport::JSON::Encoding::JSONGemEncoder::EscapedString, 2110], [Arel::Nodes::SqlLiteral, 20], [Arel::Nodes::BindParam, 10], [ActiveSupport::StringInquirer, 1]]
### JSON rendering happens ###
[[String, 157847], [ActiveSupport::JSON::Encoding::JSONGemEncoder::EscapedString, 4220], [Arel::Nodes::SqlLiteral, 30], [Arel::Nodes::BindParam, 12], [ActiveSupport::StringInquirer, 1]]

Completed 200 OK in 178ms (Views: 5.6ms | ActiveRecord: 2.3ms)

The object allocation is down by a huge amount, and the request now takes from 50ms to 200ms to respond. This is not yet completely efficient, but it is a much more acceptable value.