whats_looping

def render(curriculum)
  curriculum.books.map do |book|
    "#{book.title} by #{book.author_name}"
  end
end

def total
  subtotal * (1 + invoice.tax_rate)
end

The problem

The curriculum report is slow to render. These are the two methods involved:

def render(curriculum)
  curriculum.books.map { |book| "#{book.title} by #{book.author_name}" }.join("\n")
end

def author_name
  author.name
end

author_name loads the author with one query per book, which is an N+1. It is hard to spot because each method is one line and the loop is in a different file from the query. A profiler shows the time as spent in the database and does not point to the loop that caused it.

A hot loop with no database involved is hard to spot for the same reason:

def total
  subtotal * (1 + invoice.tax_rate)
end

def tax_rate
  Finance::Accounts.rate_for(region, issued_on)
end

Every line on an invoice asks the same invoice for its tax rate, and the rate is worked out again each time.

The fix

Ask what’s looping:

$ ra whats_looping

hot loops
· 29 call sites that ran 20+ times in one tree
app/models/curriculum.rb:66  Book#unlocked?
  400× in one call tree (DashboardController#show) · 20 distinct receivers
  median 400× per tree · 51 trees
  → per-element work: preload or batch it
app/models/curriculum.rb:66  Curriculum#prerequisites
  380× in one call tree (DashboardController#show) · 1 distinct receiver
  median 380× per tree · 51 trees
  → the same object asked again: memoise it
app/models/student.rb:15  Enrollment#completed?
  360× in one call tree (DashboardController#show) · 1 distinct receiver
  median 360× per tree · 54 trees
  → the same object asked again: memoise it
  … 26 more

The first entry is the dashboard loop that where_time_goes also ranks first: one line in Curriculum#eligible that asks twenty books twenty times each per page. The count of distinct receivers separates the two kinds of loop. Twenty different books is per-element work, and one curriculum asked 380 times is an answer that can be kept.

The two loops from the top of this page ran twice each, in a spec with two books and a spec with two invoice lines, so they rank far below these. Lower the threshold and narrow to a file to see them:

$ ra whats_looping --min 2 --file app/models/report.rb
app/models/report.rb:38  Book#author_name
  2× in one call tree (Report#render) · 2 distinct receivers
  median 2× per tree · 1 tree
  → per-element work: preload or batch it
  …

$ ra whats_looping --min 2 --file app/models/invoice_line.rb
app/models/invoice_line.rb:13  Invoice#tax_rate
  2× in one call tree (Invoice#pdf) · 1 distinct receiver
  median 2× per tree · 1 tree
  → the same object asked again: memoise it
  …

Load the authors in one query, and memoise the tax rate:

def render(curriculum)
  curriculum.books.includes(:author).map { |book| "#{book.title} by #{book.author_name}" }.join("\n")
end

def tax_rate
  @tax_rate ||= Finance::Accounts.rate_for(region, issued_on)
end

Run it again after the change. author_name is still called once per book, as it should be, and the query count falls to two. tax_rate is no longer in the list.

Where it shows up

• Over MCP, the ranked sites come back as text and structured blocks, each with its receiver count and the suggested fix.
• On the command line, run ra whats_looping, with --min to set how many repeats in one tree count as a loop.

How it works

1. Every entry point, a spec example or a request, records one call tree, and every call in the tree includes its call site.
2. Calls are grouped by tree, call site and method. A site that ran hundreds of times in a single tree is a loop.
3. The recording keeps each receiver’s object identity, which within one tree is unique. Many receivers means the loop walks a collection, and one receiver means the same object is asked the same thing repeatedly.
4. Across every recorded tree, sites are ranked by the most repeats in one tree, with the median per tree and how many trees ran the site.

Run it on your app

The output on this page comes from our example Rails app, and it is regenerated whenever a tool changes. These are the commands behind it. On your own app, run ra record first, then put your own class, method or file in their place.

ra whats_looping
ra whats_looping --min 2 --file app/models/report.rb
ra whats_looping --min 2 --file app/models/invoice_line.rb

The N+1 is app/models/report.rb:38 calling app/models/book.rb:30. The recomputed rate is app/models/invoice_line.rb:13 calling app/models/invoice.rb:44.

Reading the result

• It records calls to your methods and does not record SQL. The loop appears as calls to Book#author_name, and you find the query by opening that method. A loop that runs entirely inside a gem or core method, with no call to your own code in it, is not reported.
• Some loops are correct, because some work has to happen per element. The report is a ranked list of places to look.
• Specs are weak evidence for this tool. Test data is small, so a spec with two books is not reported as a loop until you lower --min. Recorded production runs, or a realistic seed, find far more.

Every tool reads the same recording. What gets recorded and how far to trust an answer are on the questions page.

Related tools