Recognizing N+1 in the Rails log

Where ActiveRecord querying: includes & joins left off

ActiveRecord querying: includes & joins spent seven lessons on fixing N+1. .includes, .preload, .eager_load and .strict_loading turn a lazy association access into one extra query, or a loud error, instead of one query per row. All seven lessons assumed you already knew a page had the problem. This course answers the question that comes first: how do you find out that a few hundred near-identical queries just ran instead of two, before a user complains that a page got slow?

The answer starts with the plainest tool there is: the log this app already writes on every request.

A burst from this app's log

Picture a naive version of the roadmap's course listing, one without the fix Catalog::ListCoursesQuery ships with, that calls course.lessons.count inside a loop over every active course. Running it against this app's catalog and watching log/development.log gives this:

  Catalog::Lesson Count (9.2ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5070 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.2ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 4933 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 4947 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5198 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5199 /*application='NewbieOnRails'*/
  ...
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5168 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (3.3ms)  SELECT COUNT(*) AS "count_all", "lessons"."course_id" AS "lessons_course_id" FROM "lessons" GROUP BY "lessons"."course_id" /*application='NewbieOnRails'*/

Only the middle of the burst is cut. There's one Catalog::Lesson Count line per active course, a few hundred of them, each identical except for the number after course_id = . At the very end is one different line: a GROUP BY query that answers the same question, lesson counts for every course, in one go.

That last line is what Catalog::ListCoursesQuery, this app's shipped query object, runs:

# app/queries/catalog/list_courses_query.rb
lesson_counts = ::Catalog::Lesson.group(:course_id).count

One call, one query, and a Hash of {course_id => count} that the view looks up for each card. The burst above is what the same page would log if that line were replaced by course.lessons.count inside the .each. The page would look the same, but it would run one query per course plus one, instead of 2.

What makes a burst recognizable

Three things separate an N+1 burst from an ordinary busy page.

A repeated label. Every line above says Catalog::Lesson Count, ActiveRecord's name for that query shape: the model name plus the kind of query (Load, Count, Exists?). One label appearing dozens of times in a row is the first signal. A page that touches many tables logs many different labels, not the same one over and over.

Everything is identical except one literal. Strip the number after course_id = from each line above and the queries are the same. That one varying value, almost always an id, shows it's the same Ruby call running once per row of an outer collection, not hundreds of different questions.

The count follows a collection size, not a constant. One line per active course is no coincidence; it's the definition of N+1. One query fetches N rows (the "+1", here Catalog::Course.active, which ran before the visible burst), then N more queries run, one per row.

Two config lines that make this log readable

This app's config/environments/development.rb turns on two relevant options. They were there before this lesson:

config.active_record.verbose_query_logs = true
config.active_record.query_log_tags_enabled = true

query_log_tags_enabled is why every line above ends in a SQL comment, /*application='NewbieOnRails'*/. In a browser request, the comment also includes the controller and action, like /*action='index',application='NewbieOnRails',controller='courses'*/. verbose_query_logs goes further. For a query triggered by an HTTP request, it prints a second line under the query that names the file and line that issued it. A query run from a bin/rails runner script gets no such line. Here's a pair captured from an earlier version of the roadmap page:

  SolidCache::Entry Load (0.1ms)  SELECT "solid_cache_entries"."key", "solid_cache_entries"."value" FROM "solid_cache_entries" WHERE "solid_cache_entries"."key_hash" IN (3575527472517797304) /*action='index',application='NewbieOnRails',controller='courses'*/
  ↳ app/views/catalog/courses/_course_card.html.erb:3

This pair isn't a bug, and it's worth a closer look. At the time, line 3 of _course_card.html.erb was a cache block, Rails' fragment-caching helper, backed by this app's config.cache_store = :solid_cache_store. Each card read its own cache entry, so one page load logged a run of SolidCache::Entry Load queries. That has the N+1 shape (a repeated label, one varying value, a count that follows a collection) without the cost, because a cache read isn't a problem to fix. Today the cards render as a cached collection (cached: in index.html.erb), which fetches each group's keys with one read_multi, so the run is shorter. The log shape alone can't tell an N+1 from fragment caching that works. It tells you where to look: the ↳ line names the line to read, and reading it is what tells you whether there's a problem.

Key takeaways

• The N+1 signature in a log: one query label repeated many times, identical except for one varying literal (almost always an id), with the count following an outer collection's size.
• This app's Catalog::ListCoursesQuery avoids that shape with one line, Catalog::Lesson.group(:course_id).count, which replaces one query per course with a single grouped query.
• verbose_query_logs, on in this app's development.rb, prints a ↳ file:line annotation under each query triggered by a request. Queries run from bin/rails runner don't get one.
• A repeated-query burst is a strong signal, not proof: fragment-cache reads produce the same shape and aren't a bug. That's why the next lessons build sharper tools than reading a log by eye.