Maybe you already know that “fixing” an n+1 queries problem can hurt the performance of your app…

But even if you already know it and also understand how it can happen, it could not be obvious how to know if this is will happen with your fix.

Some things that you can try are to…

• Compare the requests time
• Compare the queries load time
• Compare the produced allocations

Depending on the criticality of the fix and the volume that is handling your app you can just push to production and check there or try to simulate with the expected volume of data on development.

Try on development first

Although sometimes there will be no problem if you just push to production, if your intuition tells you that maybe the associations that you are preloading will preload to much data, you can try to simulate the expected volume of data that you will expect on production. This will help you to have more control on your tests.

Where to find the information?

You can use different tools like rack-mini-profiler or tools on your production application, like NewRelic or Skylight, but you can also take a look on your logs.

If you looks in your logs, for each request you will find something like this…

Started GET "/posts" for ::1 at 2021-10-05 18:11:18 -0500
Processing by PostsController#index as HTML
  Rendering layout layouts/application.html.erb
  Rendering posts/index.html.erb within layouts/application
  Post Load (4.2ms)  SELECT "posts".* FROM "posts" WHERE "posts"."comments_count" = $1  [["comments_count", 5]]
  ↳ app/views/posts/index.html.erb:35
  Comment Load (4.8ms)  SELECT "comments".* FROM "comments" WHERE "comments"."post_id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20) ORDER BY "comments"."id" ASC  [["post_id", 1], ["post_id", 2], ["post_id", 3], ["post_id", 4], ["post_id", 5], ["post_id", 6], ["post_id", 7], ["post_id", 8], ["post_id", 9], ["post_id", 10], ["post_id", 11], ["post_id" 12], ["post_id", 13], ["post_id", 14], ["post_id", 15], ["post_id", 16], ["post_id", 17], ["post_id", 18], ["post_id", 19], ["post_id", 20]]
  ↳ app/views/posts/index.html.erb:35
  Rendered posts/index.html.erb within layouts/application (Duration: 58.0ms | Allocations: 18269)
  Rendered layout layouts/application.html.erb (Duration: 64.0ms | Allocations: 18907)
Completed 200 OK in 92ms (Views: 50.9ms | ActiveRecord: 23.8ms | Allocations: 24737)

There, for the sql you will find…

• The sql used for the query
• The query load time
• And the place where the query was called in your code

Post Load (4.2ms)  SELECT "posts".* FROM "posts" WHERE "posts"."comments_count" = $1  [["comments_count", 5]]
  ↳ app/views/posts/index.html.erb:35
  Comment Load (4.8ms)  SELECT "comments".* FROM "comments" WHERE "comments"."post_id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20) ORDER BY "comments"."id" ASC  [["post_id", 1], ["post_id", 2], ["post_id", 3], ["post_id", 4], ["post_id", 5], ["post_id", 6], ["post_id", 7], ["post_id", 8], ["post_id", 9], ["post_id", 10], ["post_id", 11], ["post_id" 12], ["post_id", 13], ["post_id", 14], ["post_id", 15], ["post_id", 16], ["post_id", 17], ["post_id", 18], ["post_id", 19], ["post_id", 20]]
  ↳ app/views/posts/index.html.erb:35

For each rendered file you will find…

• The rendering time as “Duration”
• And the number of Allocations

Rendered posts/index.html.erb within layouts/application (Duration: 58.0ms | Allocations: 18269)
Rendered layout layouts/application.html.erb (Duration: 64.0ms | Allocations: 18907)

And at the bottom you will find the total times…

• The request time
• The time spent in views
• The time spent in ActiveRecord
• And the time in Allocations

Completed 200 OK in 92ms (Views: 50.9ms | ActiveRecord: 23.8ms | Allocations: 24737)

Practice app

I have built a little app to help you visualize why “fixing” an n+1 queries problem, can hurt the performance of your application if you preload associations with too many records.

It simulates the index page of a blog application. It has the rack-mini-profiler gem, and it shows the logs in the page to help you visualize easily the queries, request time and allocations.

By default it has an n+1 queries problem. It makes a call to the database to fetch the latest comment for each post in the list, but you can fix it with a checkbox.

It will let you compare request times combining a filter of posts by number of comments and the checkbox to “fix” the n+1 queries problem.

I explain more about it on this link: Example app to understand why some times fixing some n+1 queries can hurt performance

Related articles

• Joins does not preload
• Examples to explore possible race conditions when caching custom computed values in Rails
• Examples to learn the difference between preload, includes or eager_load
• Mistakes we make with counts in rails