where_time_goes

The problem

The student dashboard is slow, and someone has already opened a pull request to cache Curriculum#weeks_for, because it looks expensive:

class Curriculum
  def weeks_for(book)
    book.chapters.sum { |chapter| chapter.lessons.count } / LESSONS_PER_WEEK
  end

  def unlocked_for(student)
    books.select { |book| book.unlocked?(student) }
  end
end

It does look expensive. But a method that’s slow once and a method that’s called constantly are different problems, and reading the code only tells you about the first. A profiler run on your laptop tells you about one request you happened to make, not the mix your users make.

The fix

Ask which chains carry the traffic:

$ ra where_time_goes --entry DashboardController

most-travelled chains · 2 recorded runs · 18,402 calls

  1  DashboardController#show
     └ Enrollment#progress
       └ Curriculum#unlocked_for
         └ Book#unlocked?                         12,000 calls   65%
  2  DashboardController#show
     └ Enrollment#progress
       └ Curriculum#unlocked_for                     600 calls    3%
  3  DashboardController#show
     └ Report#summary
       └ Curriculum#weeks_for                         46 calls  0.2%

weeks_for runs 46 times. Book#unlocked? runs twelve thousand, because Enrollment#progress asks for the unlocked books once per book on the page, and each ask checks every book again:

class Enrollment
  def progress
    books.map { |book| Progress.new(book, unlocked: curriculum.unlocked_for(student).include?(book)) }
  end
end

Thirty dashboards, twenty books each, twenty checks per ask. That’s where the cache belongs:

class Enrollment
  def progress
    unlocked = curriculum.unlocked_for(student).to_set
    books.map { |book| Progress.new(book, unlocked: unlocked.include?(book)) }
  end
end

One call to unlocked_for per page instead of one per book. The weeks_for pull request can wait.

How it works

Every call in the recording belongs to a call tree and knows the method that made it, so each call’s chain back to its root can be rebuilt. where_time_goes rebuilds them, merges identical chains and ranks them by count. --entry narrows it to the trees that start at a controller, job or spec you name.

Chains, rather than single methods, because the same method can be cheap from one caller and hot from another. The chain tells you which caller to change.

Limits

• Traffic, not time. The recording counts calls, it doesn’t time them. A chain that runs twelve thousand times is the place to look first, but a single slow query can still hide in a chain that runs once. Use a profiler for that; use this to decide where to point it.
• Your recorded mix. Ranked from the runs you recorded. Your test suite’s mix of calls isn’t your users’ mix, so record the app itself when the ranking matters.
• App methods only. Time spent inside a gem or the database shows up as calls to the app method that called it, not as its own chain.

Related tools