where_time_goes

The problem

The student dashboard is slow, and someone has already opened a pull request to cache Curriculum#weeks_for, because the report that calls it sums it over the final books on every page:

def summary(curriculum)
  curriculum.final_books.map { |book| summary_line(book) }.join(", ") +
    " · #{curriculum.final_books.sum { |book| curriculum.weeks_for(book) }} weeks to finish"
end

weeks_for looks like the expensive part when you read the code. A method that is slow once and a method that is called constantly are different problems, though, and only the first of them is visible in the code. A profiler run on your laptop covers the one request you happened to make. The mix of requests your users make is not in it.

The fix

Ask which chains run most often:

$ ra where_time_goes --entry DashboardController --top 3
most-travelled chains
· 30 trees · 49710 calls
  1  DashboardController#show └ Enrollment#progress └ Curriculum#unlocked_for └ Curriculum#eligible └ Book#unlocked?                              12,000  24.1%
  2  DashboardController#show └ Enrollment#progress └ Curriculum#unlocked_for └ Curriculum#eligible └ Curriculum#prerequisites                    11,400  22.9%
  3  DashboardController#show └ Enrollment#progress └ Curriculum#unlocked_for └ Curriculum#eligible └ Student#completed? └ Enrollment#completed?  10,800  21.7%

weeks_for is 62 calls in the full list, a tenth of a percent. Seven in ten calls under the dashboard go through Enrollment#progress into Curriculum#unlocked_for, because progress asks for the unlocked books once per book on the page, and each of those requests checks every book again:

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

Thirty dashboards of twenty books each, with twenty eligibility checks per request for the unlocked books, make the twelve thousand calls. The cache belongs in progress:

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

That is one call to unlocked_for per page instead of one per book, and the weeks_for pull request can wait.

Where it shows up

• Over MCP, the ranked chains come back as a table your agent can read before it decides what to cache.
• On the command line, run ra where_time_goes, with --entry to pick the trees whose entry point mentions a controller, job or spec, and --top to cut the list.

How it works

Every call in the recording belongs to a call tree and records 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, with each chain’s share of every call in the selected trees. --entry keeps the trees whose entry point contains the text you give, so DashboardController matches every GET /dashboard/7 (DashboardController#show) request.

It ranks chains instead of single methods because the same method can be cheap from one caller and hot from another, and the chain includes the caller to change.

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 where_time_goes --entry DashboardController

The repeated call is app/models/enrollment.rb:20, and the traffic script requests thirty dashboards.

Reading the result

• The recording counts calls and does not time them. A chain that runs twelve thousand times is the place to look first, but a single slow query can be in a chain that runs once. Use a profiler to find that, and use this report to decide what to profile.
• The ranking comes from the runs you recorded. Your test suite makes a different mix of calls from your users, so record the app itself when you plan to act on the ranking.
• Chains are made of app methods. Time spent inside a gem or the database appears as calls to the app method that called it and does not get a chain of its own.

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

Related tools