Profiling and tuning a Rails app

The Kaksha timetable page sends 11 database queries to show 10 slots, and every teacher opens it at the start of each period. Before you change a line of code, work out where its milliseconds go: Rails’ own log already splits them, the development server adds a header that the browser’s developer tools show beside the request, and a sampling profilerprofiler: A tool that reports where a program spends its time, either by sampling what is running at regular intervals or by recording every call; sampling costs far less, so it can watch real requests. turns a run into a table of the methods that took the time.

Tuning a Rails app without a measurement is guessing. Measure one request end to end first, then change one server setting at a time and measure again: YJIT, Puma’s threads and workers, the database pool, the memory allocator, and budgets that fail the build when a page slows down again.

Three ways to see where a request’s milliseconds went

The first split needs no tool. Every controller action ends with a Completed line in the Rails log, in the form Completed 200 OK in <total>ms (Views: <ms> | ActiveRecord: <ms> (<n> queries, <n> cached) | GC: <ms>): the total, the render, the SQL with its query count, and the garbage collector’s pauses. Rails takes the queries that ran during the render out of Views, so no millisecond is counted twice.

The second split is a response header. ActionDispatch::ServerTiming collects every Active Support notification the request fires, adds up the milliseconds of each name, and writes a Server-TimingServer-Timing: A W3C response header in which a server reports how a request's time was spent, one name;dur=<ms> entry per metric, shown by the browser's developer tools next to the request. header of name;dur=<ms> entries, the form the W3C specification defines. A new app’s development.rb sets config.server_timing = true and production leaves it off, which suits the specification’s privacy section: these metrics can expose sensitive application and infrastructure information. The run calls the N+1 version of /timetable twice and prints both splits:

require "rails"
require "active_record/railtie"
require "action_controller/railtie"
require "action_view/railtie"
require "stringio"

# A one-file Rails 8.1 app that turns Server-Timing on and prints, for one slow /timetable
# request, the Completed line of the Rails log and the response's Server-Timing header.
# The slow bit is a deliberate N+1 inside a view loop.

LOG = StringIO.new

class ServerTimingApp < Rails::Application
  config.load_defaults 8.1
  config.eager_load = false
  config.logger = ActiveSupport::Logger.new(LOG)    # the log goes to memory; the run prints its Completed line
  config.secret_key_base = "x" * 64
  config.hosts.clear
  config.server_timing = true                       # the middleware ActionDispatch::ServerTiming installs on true
  config.action_controller.perform_caching = false  # the slow version does no caching
end

ENV["DATABASE_URL"] = "sqlite3::memory:"
ServerTimingApp.initialize!

ActiveRecord::Schema.verbose = false
ActiveRecord::Schema.define do
  create_table :students, force: true do |t|
    t.string :name
  end
  create_table :slots, force: true do |t|
    t.integer :student_id
    t.string :period
  end
end

class Student < ActiveRecord::Base; end
class Slot < ActiveRecord::Base
  belongs_to :student
end

10.times do |i|
  s = Student.create!(name: "Student #{i + 1}")
  Slot.create!(student_id: s.id, period: "P#{i + 1}")
end

class TimetableController < ActionController::Base
  def index
    @slots = Slot.all                        # one SELECT for the slots
    render inline: <<~ERB                    # ten more SELECTs for each slot.student (N+1)
      <ul>
      <% @slots.each do |slot| %>
        <li><%= slot.period %>: <%= slot.student.name %></li>
      <% end %>
      </ul>
    ERB
  end
end

ServerTimingApp.routes.draw { get "/timetable" => "timetable#index" }

# Call the slow endpoint twice. The entry names stay the same; the milliseconds move
# from run to run. A subscriber counts the queries each request sends.
2.times do |n|
  queries = 0
  counter = ->(*) { queries += 1 }
  LOG.truncate(0)
  LOG.rewind
  status, headers, body = ActiveSupport::Notifications.subscribed(counter, "sql.active_record") do
    ServerTimingApp.call(Rack::MockRequest.env_for("/timetable"))
  end
  puts "Request #{n + 1}: HTTP #{status}, body #{body.each.to_a.join.bytesize} bytes, #{queries} SQL queries"
  puts "Rails log: #{LOG.string.lines.grep(/\ACompleted /).last.to_s.strip}"
  entries = headers["Server-Timing"].to_s.split(", ")
  puts "Server-Timing entries (#{entries.length}):"
  entries.sort.each { |e| puts "  #{e}" }
  puts
end

Request 1: HTTP 200, body 263 bytes, 11 SQL queries
Rails log: Completed 200 OK in 13ms (Views: 12.5ms | ActiveRecord: 0.4ms (11 queries, 0 cached) | GC: 0.0ms)
Server-Timing entries (5):
  instantiation.active_record;dur=0.15
  process_action.action_controller;dur=13.12
  render_template.action_view;dur=2.92
  sql.active_record;dur=0.41
  start_processing.action_controller;dur=0.01

Request 2: HTTP 200, body 263 bytes, 11 SQL queries
Rails log: Completed 200 OK in 2ms (Views: 2.1ms | ActiveRecord: 0.2ms (11 queries, 0 cached) | GC: 0.0ms)
Server-Timing entries (5):
  instantiation.active_record;dur=0.13
  process_action.action_controller;dur=2.36
  render_template.action_view;dur=2.13
  sql.active_record;dur=0.21
  start_processing.action_controller;dur=0.00

Ten rows in memory keep the milliseconds small, but both requests send 11 queries: one for the slots, then one per slot for its student, because the view calls slot.student.name in its loop. That N+1N+1 query: Reading a list with one query and then one more query per row of it, usually by following an association inside a loop; preloading the association turns the many queries into a few. More in “Associations” shows as one sql.active_record entry, the sum of all eleven. The entries overlap: process_action.action_controller times the whole action, with the render and the queries inside it. Step through the same request to see where each entry starts and what it covers:

The third split names the code. Profiling answers what the first two leave open: which methods took the time. A sampling profilersampling profiler: A profiler that records the running stack of each thread at a fixed interval and reports which frames were seen most often; Vernier samples every 500 microseconds by default. records what each thread runs every few hundred microseconds, so the busiest methods rise to the top. Vernier samples every 500 microseconds by default, and its README puts a profiled CPU-bound loop within a few percent of its normal speed. rack-mini-profiler adds a speed badge to every HTML page.

Profiling shows where one request spends its time; tuning a Rails app decides how many requests the server carries at once. Six settings decide that:

• YJITYJIT: Ruby's just-in-time compiler, built into CRuby, which turns frequently run code into machine code while the program runs: faster Ruby in exchange for more memory., Ruby’s just-in-time compiler: Rails 8.1 sets config.yjit = !Rails.env.local?, so it runs everywhere except development and test.
• Puma threads share one process; only one runs Ruby at a time, so extra threads help only while requests wait on the database or network.
• Puma workersPuma worker: A child process that Puma forks in cluster mode; each serves requests with its own threads, so several workers run Ruby on several CPU cores at the same time. are forked processes with their own threads, so several workers use several CPU cores at once.
• The connection poolconnection pool: The set of database connections Active Record keeps per process; a thread checks one out while it needs it, and a thread that finds none free waits, then raises ActiveRecord::ConnectionTimeoutError. lends each thread a database connection; with fewer connections than threads, a thread waits and then raises ActiveRecord::ConnectionTimeoutError.
• jemallocjemalloc: An alternative memory allocator a Rails image preloads with LD_PRELOAD, which holds less memory than the default allocator under a threaded server. and BootsnapBootsnap: A gem that caches costly steps of booting a Ruby app, such as compiling its Ruby files, so later boots are faster; the Dockerfile of a new Rails app builds its cache into the image. come with the generated Dockerfile: an allocator that fragments memory less, and a cache that makes boots faster.
• A performance budgetperformance budget: A limit on a number users feel, such as the queries a page sends or its p95 time, checked by a test that fails the build when the number crosses the limit. is a test that counts a page’s queries or measures its p95 and fails the build when the page gets slower.

Practise: predict the split, then run it

Copy examples/server_timing.rb, make one change at a time, and before each run write down the query count and the Server-Timing entries you expect to grow:

1. Change Slot.all to Slot.includes(:student).
2. Add sleep 0.05 at the start of the index action, a stand-in for a slow call to another service.
3. Seed 100 students instead of 10, with and without the change from step 1.

Then test your predictions with the questions below, which begin with the ideas you have missed most.

Reading Vernier's top frames, before and after a fix Pro: opens with a Pro, Premium or Ultimate pass

YJIT, threads, workers and a pool that does not time out Pro: opens with a Pro, Premium or Ultimate pass

A query budget and a p95 budget your tests enforce Pro: opens with a Pro, Premium or Ultimate pass

Interview questions

What does the Server-Timing header show, and why is it on in development only?

It lists the Active Support notifications a request fired, one name;dur=<ms> entry per notification name, with the milliseconds of every event of that name added up. A Rails request shows entries such as process_action.action_controller for the whole action, render_template.action_view for the view and sql.active_record for all its queries together, and the browser’s developer tools show each entry beside the request. ActionDispatch::ServerTiming adds the header when config.server_timing is true, which a new app’s development.rb sets. Production leaves it off because every visitor’s browser would receive the names and timings of the app’s internals, the kind of information the specification’s privacy section warns about; production timings belong in a monitoring service or a profiler that keeps them on the server.

The three questions below start from symptoms seen in production. For each, say what you would measure first, then check your plan against the question’s first step.

Key takeaways

• The Rails log’s Completed line splits a request into total, render, SQL and GC time and counts its queries.
• In development, the Server-Timing header adds one entry per notification name, so an N+1 shows as many queries summed into one sql.active_record entry.
• A sampling profiler such as Vernier names the methods behind the time and costs little enough to point at a real request.
• YJIT, Puma’s threads and workers, the connection pool, jemalloc with Bootsnap, and performance budgets decide how fast a Rails server answers, and each is worth changing only with a measurement before and after.