Although there are tools that can help you detect n+1 queries before they hit production, I think that is good to be able to identify n+1 queries directly by watching your logs…
Not all the tools will tell you exactly that you have n+1 queries, and sometimes the ones that will tell you, can give you false negatives.
Also I think that, although there is hardly no training anywhere for this ability, is always an expected ability for an experienced rails developer.
As you may know, an n+1 queries problem means that a query is executed for every result of a previous query.
For example, given a Post that has many comments, If you execute the next code…
Post.map(&:comments).map(&:to_a)
You will execute…
Post.all)n queries to fetch the comments of each post(post.comments)So, if you go to the console and test this code…
If there are 2 posts, it will execute 3 queries (2 + 1), and you will see in your logs, something like…
> Post.first(2).map(&:comments).map(&:to_a)
Post Load (0.8ms) SELECT "posts".* FROM "posts" ORDER BY "posts"."id" ASC LIMIT $1 [["LIMIT", 2]]
Comment Load (0.4ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 1]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 2]]
And if there are 5 posts, it will execute 6 queries (5 + 1), and you will see in your logs, something like…
> Post.first(5).map(&:comments).map(&:to_a)
Post Load (0.8ms) SELECT "posts".* FROM "posts" ORDER BY "posts"."id" ASC LIMIT $1 [["LIMIT", 5]]
Comment Load (0.4ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 1]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 2]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 3]]
Comment Load (0.2ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 4]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 5]]
And if there are 1000 posts, it will execute 1001 queries (1000 + 1), and in the same way you will see in your logs…
> Post.first(1000).map(&:comments).map(&:to_a)
Post Load (0.8ms) SELECT "posts".* FROM "posts" ORDER BY "posts"."id" ASC LIMIT $1 [["LIMIT", 1000]]
Comment Load (0.4ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 1]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 2]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 3]]
Comment Load (0.2ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 4]]
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 5]]
#...
Comment Load (0.3ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" ASC [["post_id", 1000]]
The previous examples show examples taken from the rails console, but as you can see in the next example…
When you start the server, on your logs, after each query, rails will show you where is the code that executes that query.
Started GET "/posts" for ::1 at 2021-11-10 06:47:40 -0600
Processing by PostsController#index as HTML
Rendering layout layouts/application.html.erb
Rendering posts/index.html.erb within layouts/application
Rendered posts/_filters.html.erb (Duration: 6.5ms | Allocations: 2354)
Post Load (1.2ms) SELECT "posts".* FROM "posts" WHERE "posts"."comments_count" = $1 [["comments_count", 5]]
↳ app/views/posts/index.html.erb:5
Comment Load (3.4ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" DESC LIMIT $2 [["post_id", 1], ["LIMIT", 1]]
↳ app/views/posts/_post.html.erb:6
Comment Load (1.0ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" DESC LIMIT $2 [["post_id", 2], ["LIMIT", 1]]
↳ app/views/posts/_post.html.erb:6
Comment Load (1.0ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" DESC LIMIT $2 [["post_id", 3], ["LIMIT", 1]]
↳ app/views/posts/_post.html.erb:6
Comment Load (1.0ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" DESC LIMIT $2 [["post_id", 4], ["LIMIT", 1]]
↳ app/views/posts/_post.html.erb:6
Comment Load (1.0ms) SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = $1 ORDER BY "comments"."id" DESC LIMIT $2 [["post_id", 5], ["LIMIT", 1]]
↳ app/views/posts/_post.html.erb:6
#...
Rendered collection of posts/_post.html.erb [20 times] (Duration: 84.5ms | Allocations: 34947)
Rendered posts/index.html.erb within layouts/application (Duration: 107.3ms | Allocations: 45186)
Rendered layout layouts/application.html.erb (Duration: 175.0ms | Allocations: 77162)
Completed 200 OK in 204ms (Views: 147.6ms | ActiveRecord: 34.7ms | Allocations: 86545)
So, if you look out for this two things, repeated queries that are executed from the sample place … you can be almost sure that you have an n+1 queries problem in that place.
Learn just enough fundamentals to be fluent preloading associations with ActiveRecord, and start helping your team to avoid n+1 queries on production.