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 takes four seconds to render. Nothing in it looks slow:

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

class Book < ApplicationRecord
  belongs_to :author

  def author_name = author.name
end

author_name loads the author, one query per book, and a curriculum has two hundred books. It’s the classic N+1, and it hides well: each method is one line, the loop is in one file and the query is in another. Profilers show the time in the database, not the loop that caused it.

Hot loops hide the same way without any database at all:

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

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

Every line on an invoice asks the same invoice the same question, and each time it’s worked out again.

The fix

Ask what’s looping:

$ ra whats_looping

app/models/report.rb:3  Book#author_name
  212× in one call tree (Report#render) · 212 distinct receivers
  median 184× per tree · 1,044 production runs
  → per-element work: preload or batch it

app/models/invoice_line.rb:2  Invoice#tax_rate
  180× in one call tree (Invoice#pdf) · 1 distinct receiver
  median 40× per tree · 6,310 production runs
  → the same object asked again: memoise it

The distinct receivers tell the two apart. Two hundred different books means per-element work, so load the authors in one go:

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

One invoice asked a hundred and eighty times means the answer can be kept:

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

Run it again after the change: author_name is still called 212 times, and should be, but the report no longer takes four seconds. tax_rate drops off the list.

How it works

1. Call trees. Every entry point, a spec example or a request, records one call tree, and every call in it names its call site.
2. Count per tree. Calls are grouped by tree, call site and method. A site hit hundreds of times in a single tree is a loop.
3. Count receivers. The recording keeps each receiver’s object identity, which within one tree is unique. Many receivers means the loop walks a collection; one receiver means the same object is asked the same thing repeatedly.
4. Rank. Across every recorded tree, sites are ranked by how many times they repeat and how often their tree runs. Record production and the ranking follows real traffic.

Limits

• It sees your methods, not your SQL. The loop shows up as 212 calls to Book#author_name. The query is what you find when you open it. A loop entirely inside a gem or core method, with no call to your own code in it, isn’t seen.
• A loop isn’t always a problem. Some work has to happen per element. The report is a list of leads, ranked, not a list of bugs.
• Specs make poor evidence here. Test data is small, so a spec with three books won’t look like a loop. Recorded production runs, or a realistic seed, find far more.

Related tools