Ruby on Rails profiling, four tools on one slow request
A slow Rails request gives you one line of evidence for free, and that line is
Completed 200 OK in 62ms (Views: 33.3ms | ActiveRecord: 28.6ms (201 queries, 80 cached) | GC: 1.3ms).
The arithmetic closes. Views plus ActiveRecord is 61.9 of 62 milliseconds, so nothing is hiding. And
there is still nothing in it you can act on, because 33.3 ms of "Views" is not a place in your code,
it is a layer, and 28.6 ms across 201 queries is 0.14 ms each, which is fast enough that nobody
suspects the database. Profiling is the work of turning that layer into a line number, and the four
tools that do it here disagree with each other in ways worth knowing before you pick one.
Conditions, because a number without them is not checkable. Apple M2 Max, 12 cores, macOS
arm64-darwin25, Ruby 4.0.5 (2026-05-20 revision 64336ffd0e) with PRISM and without YJIT. Rails
8.1.3.1, puma 8.0.2, pg 1.6.3, PostgreSQL 17.7 (Homebrew) on port 15432 over loopback. stackprof
0.2.28, vernier 1.11.0, rack-mini-profiler 5.0.0, memory_profiler 1.1.0, benchmark-ips 2.15.1.
ApacheBench 2.3 from /usr/sbin/ab. The application is a scratch Rails app with 20 authors, 600
posts and 4,596 comments, running RAILS_ENV=production with RAILS_MAX_THREADS=1 against a local
database. Request timings marked in-process are driven by ActionDispatch::Integration::Session
inside bin/rails runner, which skips the socket and Puma; the ApacheBench figures go over a real
socket.
The page under the microscope renders 100 posts through a collection partial:
<li>
<strong><%= post.title %></strong>
by <%= post.author.name %>
(<%= post.comments.count %> comments)
<p><%= post.excerpt %></p>
</li>
Post#excerpt is pure Ruby with no I/O in it, which is deliberate: a profiler has to be able to
attribute it to the model and not to the database.
def excerpt
words = body.split(/\s+/)
words.each_with_index.map { |w, i| i.even? ? w.upcase : w.downcase }.first(40).join(" ")
end
What the log line can and cannot say
Three consecutive requests to that page, RAILS_ENV=production, logger at info, pasted from the
run:
Completed 200 OK in 63ms (Views: 33.1ms | ActiveRecord: 29.5ms (201 queries, 80 cached) | GC: 0.7ms)
Completed 200 OK in 59ms (Views: 35.6ms | ActiveRecord: 23.6ms (201 queries, 80 cached) | GC: 2.8ms)
Completed 200 OK in 62ms (Views: 33.3ms | ActiveRecord: 28.6ms (201 queries, 80 cached) | GC: 1.3ms)
Two things in there are worth more than they look. 201 queries is the entire bug, stated in the
first line of evidence anybody sees, and it is routinely read past because the number beside it is
small. And Views is not what most people think it is: Rails subtracts the database time spent
during rendering from it, in ActiveRecord::Railties::ControllerRuntime#cleanup_view_runtime, which
is why the two numbers sum to the total rather than overlapping. So "Views: 33.3ms" means 33.3 ms of
non-database work somewhere under render, across a template, a layout, a collection partial and
whatever the models do when the template calls them.
The same page in development, with the same data, reports
Completed 200 OK in 210ms (Views: 174.6ms | ActiveRecord: 34.7ms (201 queries, 80 cached) | GC: 29.3ms).
Not the same page 3.4 times slower for interesting reasons: the same page with eager loading off,
template reloading on and the log subscriber running at debug. A profile taken in development
tells you about development. The cost of that for view work specifically, measured, is in
Rails render partial.
Twelve lines in an initializer, and no gem
ActiveSupport::Notifications is already instrumenting everything in the request, and the most
common Rails performance bug is visible from nothing more than grouping sql.active_record by
payload[:name]. Dropped into config/initializers/request_budget.rb:
if ENV["REQUEST_BUDGET"] == "1"
sql = nil
ActiveSupport::Notifications.monotonic_subscribe("start_processing.action_controller") do
sql = Hash.new(0.0)
end
ActiveSupport::Notifications.monotonic_subscribe("sql.active_record") do |_name, start, finish, _id, payload|
sql[payload[:name].to_s] += (finish - start) * 1000.0 if sql
end
ActiveSupport::Notifications.monotonic_subscribe("process_action.action_controller") do |_name, start, finish, _id, payload|
total = (finish - start) * 1000.0
named = sql.sort_by { |_, ms| -ms }.first(3).map { |name, ms| format("%s %.2f", name, ms) }
Rails.logger.info format("BUDGET %s#%s total %.2f ms | db %.2f ms over %d queries | %s",
payload[:controller], payload[:action], total,
payload[:db_runtime], payload[:queries_count], named.join(", "))
end
end
What it printed, six requests, the first one cold:
BUDGET PostsController#index total 108.41 ms | db 49.48 ms over 201 queries | Comment Count 25.85, SCHEMA 16.45, Author Load 3.71
BUDGET PostsController#index total 57.12 ms | db 24.63 ms over 201 queries | Comment Count 20.18, Author Load 2.51, Post Load 1.94
BUDGET PostsController#index total 58.74 ms | db 22.45 ms over 201 queries | Comment Count 17.56, Author Load 3.00, Post Load 1.90
BUDGET PostsController#index total 59.40 ms | db 23.85 ms over 201 queries | Comment Count 20.02, Author Load 2.50, Post Load 1.33
BUDGET PostsController#index total 56.82 ms | db 24.56 ms over 201 queries | Comment Count 20.55, Author Load 2.42, Post Load 1.58
BUDGET FixedPostsController#index total 20.64 ms | db 3.79 ms over 3 queries | Comment Count 2.41, Post Load 1.14, Author Load 0.25
Comment Count 20.18 is the answer. Twenty milliseconds of a 57 ms request are spent running
SELECT COUNT(*) once per post, and the name comes free because Active Record already labels every
query with the model and the operation. The cold first request is worth keeping in the output too:
SCHEMA 16.45 is the column metadata load, it happens once per process, and it is the single most
common reason a first measurement is discarded as an outlier when it should have been read.
Use monotonic_subscribe rather than subscribe. The five-argument subscribe yields Time
objects and the monotonic version yields floats from CLOCK_MONOTONIC, which is the clock that does
not move when NTP adjusts the system time. I expected that to also be measurably cheaper and it is
not: over the 201 events of one request the two subscribers summed to 24.86 ms and 24.38 ms, and
Time.now benchmarks at 12.9M calls per second against 14.8M for
Process.clock_gettime(Process::CLOCK_MONOTONIC). Correctness is the reason to prefer it, not speed.
The cost of this approach is one block call per event, and one request here fires 410 of them: 201
sql.active_record, 102 !render_template.action_view, 101 instantiation.active_record, and six
others. That is fine for a development initializer and it is not a production subscriber, because a
subscriber that allocates per request is a memory shape all of its own, measured in
Finding a Rails memory leak.
StackProf names the method and the line
StackProf gives you the thing the notifications subscriber cannot: attribution inside your own Ruby, where there is no instrumentation to group by. Twenty in-process requests, wall mode, after a warm-up:
StackProf.run(mode: :wall, interval: 1000, out: "tmp/final-wall.dump") do
20.times { session.get "/posts" }
end
==================================
Mode: wall(1000)
Samples: 1281 (0.08% miss rate)
GC: 68 (5.31%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
336 (26.2%) 336 (26.2%) PG::Connection#exec_params
113 (8.8%) 113 (8.8%) String#split
94 (7.3%) 94 (7.3%) PG::Connection#exec_prepared
37 (2.9%) 37 (2.9%) (sweeping)
31 (2.4%) 31 (2.4%) (marking)
182 (14.2%) 19 (1.5%) Post#excerpt
1149 (89.7%) 18 (1.4%) Enumerable#map
1281 samples over 20 requests at one sample per millisecond is 64 ms a request, which matches the
log line, and that is the check to run first on any profile: if the sample count does not match the
wall clock you were measuring something else. The two PG::Connection frames are 33.5 percent, which
matches the log line's ActiveRecord share. String#split at 8.8 percent is new information: the log
line had it filed under Views.
The drill-down is the part almost nobody uses and the reason to reach for StackProf at all:
$ stackprof tmp/final-wall.dump --method 'Post#excerpt'
Post#excerpt (app/models/post.rb:7)
samples: 19 self (1.5%) / 182 total (14.2%)
callers:
182 ( 100.0%) #<Class:0x0000000127bb78a8>#_app_views_posts__post_html_erb__3360847884821076055_6032
37 ( 20.3%) Enumerable#map
callees (163 total):
113 ( 69.3%) String#split
61 ( 37.4%) Enumerable#map
9 ( 5.5%) String#downcase
9 ( 5.5%) String#upcase
4 ( 2.5%) Post::GeneratedAttributeMethods#body
3 ( 1.8%) Array#join
1 ( 0.6%) Array#first
code:
| 7 | def excerpt
117 (9.1%) | 8 | words = body.split(/\s+/)
102 (8.0%) / 19 (1.5%) | 9 | words.each_with_index.map { |w, i| i.even? ? w.upcase : w.downcase }.first(40).join(" ")
| 10 | end
The absolute path of the scratch application is cut out of that paste and out of the allocation report below; nothing else in either is edited.
Line 8 is 9.1 percent of the whole request. A regex split on a text column, in a method nobody thought was expensive, in a partial rendered 100 times.
Where StackProf stops is the caller line. _app_views_posts__post_html_erb__3360847884821076055_6032
is the compiled method Action View generated for _post.html.erb, and that name is not stable.
Booting the same application twice and asking for the same method gives
_app_views_posts__post_html_erb__2915898293895969708_6032 and
_app_views_posts__post_html_erb___4291888307111575962_6032. So you cannot grep for it, you cannot
diff two dumps on it, and it points at a template rather than at a line in one.
What StackProf costs, and the flag you will forget
StackProf's overhead is the reason it is the default choice. Fifty one requests per row, all in one process, two baselines taken to show the noise floor:
no profiler median 59.28 ms p10 54.04 p90 65.50
StackProf.run mode: :wall, interval: 1000 median 61.93 ms p10 57.12 p90 69.68
StackProf.run mode: :wall, interval: 100 median 65.94 ms p10 60.40 p90 73.49
StackProf.run raw: true median 60.56 ms p10 56.70 p90 65.29
no profiler, again median 57.91 ms p10 51.38 p90 65.97
At the default 1000 microseconds it costs about 4 percent, which is barely outside the 1.4 ms gap
between two identical baselines. Drop the interval to 100 microseconds and it costs 11 percent, which
is real and is the price of ten times the samples. raw: true costs nothing in time and 20.7x in
disk: 1,926,549 bytes against 92,904 for the same 20 requests. You need it for a flamegraph, and the
failure mode if you forget is the only error message StackProf will give you about it:
$ stackprof tmp/p-wall.dump --d3-flamegraph
report.rb:247:in 'StackProf::Report#print_d3_flamegraph': profile does not include raw samples (add `raw: true` to collecting StackProf.run) (RuntimeError)
StackProf's cpu mode gave two different wrong answers here
mode: :cpu is the setting that sounds like the right one for a page that is burning CPU, and on
this laptop it is unusable. Two runs of the same twenty requests, minutes apart, no code change
between them. The first named PG::Connection#exec_params at 66.1 percent. The second named this:
==================================
Mode: cpu(1000)
Samples: 770 (0.00% miss rate)
GC: 65 (8.44%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
520 (67.5%) 520 (67.5%) Process.clock_gettime
34 (4.4%) 34 (4.4%) (marking)
31 (4.0%) 31 (4.0%) (sweeping)
26 (3.4%) 26 (3.4%) PG::Connection#exec_params
16 (2.1%) 16 (2.1%) String#split
Process.clock_gettime is not two thirds of this request. A TracePoint on :c_call counted 2,183
calls to it in one GET /posts, and benchmark-ips measures it at 14.8M calls a second, so the honest
figure is 0.147 ms, or 0.24 percent of a 60 ms request. The profiler is out by a factor of 275. The
frame is dense in the call graph because Rails reads the clock around every instrumented event, which
makes it a likely place for a deferred signal to land, and landing is what a sampling profiler counts.
The sample yield is the measurable half of the problem. Same block, four configurations, with the wall clock and the process CPU time measured around each one:
mode=wall interval=1000 wall= 1441.5ms cpu= 449.8ms samples=1441 expected_at_interval=1442 sleep_self=1003
mode=wall interval=10000 wall= 1448.6ms cpu= 439.5ms samples=144 expected_at_interval=145 sleep_self=103
mode=cpu interval=1000 wall= 1471.8ms cpu= 435.7ms samples=133 expected_at_interval=436 sleep_self=5
mode=cpu interval=10000 wall= 1477.1ms cpu= 431.6ms samples=34 expected_at_interval=43 sleep_self=1
Wall mode is exact: 1441 samples for 1441.5 ms, 144 for 1448.6 ms. CPU mode delivered 133 samples for
435.7 ms of CPU where 436 were asked for, and charged five of them to Kernel#sleep, which consumes
no CPU at all. The mechanism is visible in the extension source: ext/stackprof/stackprof.c:240
arms ITIMER_REAL for wall mode and ITIMER_PROF for cpu mode, with SIGALRM and SIGPROF
respectively at line 235. On this machine ITIMER_PROF does not fire at the interval it is given,
and a sampling profiler that gets under a third of the samples it asked for is a profiler whose top
frame is an accident.
The position: use mode: :wall on macOS, always, and treat any cpu-mode profile taken here as
unreadable rather than as a second opinion. What would change it is the operating system. The
sleep_self=5 row is the tell that would be worth re-running on Linux, where ITIMER_PROF is
implemented, before repeating any of this.
Vernier annotates the ERB
Vernier 1.11.0 answers the question StackProf leaves open, which is which line of the template. Same twenty requests, same process:
Vernier.profile(out: "tmp/final-vernier.json") { 20.times { session.get "/posts" } }
vernier view reads the result in the terminal, with no browser and no upload to
profiler.firefox.com, which is worth knowing because the file format is Firefox Profiler JSON and
every tutorial sends you there. Twenty requests produced 3,640,238 bytes of it.
$ vernier view --top 6 -- tmp/final-vernier.json
+---------+------+-----------------------------------------------------------------------------------------------+
| Samples | % | name |
+---------+------+-----------------------------------------------------------------------------------------------+
| 787 | 33.5 | PG::Connection#exec_params |
| 221 | 9.4 | String#split |
| 142 | 6.0 | PG::Connection#exec_prepared |
| 37 | 1.6 | Post#excerpt |
| 36 | 1.5 | PG::Result#values |
| 33 | 1.4 | Enumerable#map |
+---------+------+-----------------------------------------------------------------------------------------------+
================================================================================
app/views/posts/_post.html.erb
--------------------------------------------------------------------------------
TOTAL | SELF | LINE SOURCE
| | 1 <li>
0.2% | 0.0% | 2 <strong><%= post.title %></strong>
22.9% | 0.0% | 3 by <%= post.author.name %>
55.3% | 0.2% | 4 (<%= post.comments.count %> comments)
15.7% | 0.0% | 5 <p><%= post.excerpt %></p>
Fifty five percent of the request is one ERB expression, post.comments.count, and 22.9 percent is
the one above it. That is the whole answer to the page, on four lines, in the file the person who
broke it was editing. The top-frames table above it says PG::Connection#exec_params and is true and
useless: every Rails page in the world has libpq at the top of a wall profile.
Vernier costs more than StackProf and the gap is not small. Same process, 31 requests a row:
no profiler median 66.85 ms p10 59.73 p90 69.61
StackProf.run wall interval:1000 median 69.29 ms p10 63.13 p90 82.79
Vernier.profile wall (default interval 500us) median 86.52 ms p10 80.21 p90 93.26
no profiler, again median 66.27 ms p10 61.71 p90 74.65
Thirty percent against four percent. For a page you are about to spend an afternoon on, 30 percent is nothing and the ERB attribution is worth it. For a profile you leave running to catch something intermittent, it is not, and that is the split I would draw between the two tools rather than any claim that one is better.
rack-mini-profiler more than doubled the page it was measuring
rack-mini-profiler puts the timings in the corner of the page in a browser, which is the friendliest
interface of anything here and the reason it is usually the first thing installed. It is also, at its
defaults, the most invasive. ApacheBench over a real socket, 120 requests, one at a time, same Puma
process, with ?pp=skip as the control:
--- /posts?pp=skip
Failed requests: 0
Requests per second: 17.69 [#/sec] (mean)
Time per request: 56.526 [ms] (mean)
--- /posts?pp=no-backtrace
Failed requests: 0
Requests per second: 16.38 [#/sec] (mean)
Time per request: 61.036 [ms] (mean)
--- /posts?pp=normal-backtrace
Failed requests: 0
Requests per second: 6.98 [#/sec] (mean)
Time per request: 143.266 [ms] (mean)
--- /fixed_posts?pp=skip
Time per request: 17.313 [ms] (mean)
--- /fixed_posts?pp=normal-backtrace
Time per request: 18.386 [ms] (mean)
normal-backtrace is the default. The cost is a Ruby backtrace captured per SQL query, filtered
through c.backtrace_includes = [/^\/?(app|config|lib|test)/], and this page runs 201 of them. The
last two rows are the same measurement against the fixed 3 query version of the same page on the same
server: 17.313 ms to 18.386 ms, or 6.2 percent. So the overhead scales with the query count, which is
to say it scales with the bug you are hunting, and the worse your N+1 the more rack-mini-profiler
exaggerates it. The ranking survives, the numbers do not, and ?pp=no-backtrace gets you back to
within 8 percent at the cost of the SQL stack traces that are half the reason to use it.
Two defaults in 5.0.0 will waste an afternoon if you do not know them, both in
lib/mini_profiler_rails/railtie.rb. The badge does not appear outside development and test, because
line 38 sets c.authorization_mode = :allow_authorized unless Rails.env.local?, and you have to
call Rack::MiniProfiler.authorize_request yourself. And pp=flamegraph, pp=profile-memory and
pp=analyze-memory answer with
This feature is disabled by default, to enable set the enable_advanced_debugging_tools option to true in Mini Profiler config.
until you set it.
An allocation profile answers a different question
?pp=profile-memory runs memory_profiler over the request and returns a text report, and it ranked
the same page differently from every timing tool above:
Total allocated: 5533081 bytes (89778 objects)
Total retained: 944783 bytes (6424 objects)
allocated memory by location
-----------------------------------
1569600 app/models/post.rb:8
1288000 app/models/post.rb:9
273895 activemodel-8.1.3.1/lib/active_model/type/string.rb:39
239957 activesupport-8.1.3.1/lib/active_support/core_ext/string/output_safety.rb:71
128160 activerecord-8.1.3.1/lib/active_record/relation.rb:77
The wall profile said _post.html.erb:4, the N+1. The allocation profile says post.rb:8, the regex
split, at 1,569,600 bytes in 30,200 objects per request. Neither is wrong. Two hundred and one small
indexed queries cost a lot of time and almost no memory, and one regex split over 100 rows of 2.5 kB
text costs almost no time relative to the queries and 1.5 MB of garbage. Whether that garbage matters
depends on a question the profile cannot answer, which is what your GC pressure looks like across a
whole worker rather than inside one request. The article for that is
Finding a Rails memory leak; the point here is only that "which line is
slow" and "which line allocates" are two different questions and the tools answer one each.
memory_profiler's cost is 6.6x. The same request measured in the same process was 60.48 ms plain and
399.28 ms inside MemoryProfiler.report, because it hooks every allocation. Nothing about its output
is a timing.
The two fixes the profiles named, and what they were worth
Both fixes come straight off the ERB annotation. post.author.name at 22.9 percent is
includes(:author). post.comments.count at 55.3 percent is not, because a preloaded association
still runs SELECT COUNT(*) per row, which is the trap laid out in
Rails N+1 queries, from includes to strict_loading; it needs the
counts loaded once and handed to the partial:
@posts = Post.where(status: "published").includes(:author).order(created_at: :desc).limit(100)
@counts = Comment.where(post: @posts).group(:post_id).count
Then the second profile names the next thing, and it is not what the first profile ranked third.
Vernier put String#split at 9.4 percent of /posts and at 33.0 percent of the fixed page, where it
is now the top frame. Replacing
body.split(/\s+/) with body.split produces identical tokens for all 600 post bodies and is 3.96x
faster on 100 of them, 5.86 ms against 1.48 ms an iteration under benchmark-ips. Three endpoints,
byte-identical 44,973 byte responses, 31 in-process requests each, all in one process:
/posts median 53.59 ms p10 49.48 p90 57.07 queries 201 db_runtime 14.52 ms view_runtime 41.01 ms
/fixed_posts median 14.51 ms p10 13.68 p90 15.34 queries 3 db_runtime 1.15 ms view_runtime 11.47 ms
/final_posts median 10.24 ms p10 9.42 p90 11.31 queries 3 db_runtime 1.16 ms view_runtime 8.38 ms
5.2x, and the second fix is a third of it. Nobody would have found the second fix from the log line,
because after the first fix the log line reads Views: 11.5ms and looks finished. Re-profile after
every fix, because the ranking is not stable under its own changes: the item that was third became
first, and the share of String#split went up while its cost per request went down.
Your integration tests count queries differently from production
A profiling habit that breaks quietly: asserting on query counts in a request spec and believing the
number. The same action, driven by the same ActionDispatch::Integration::Session class, reports
different Active Record cache behaviour in the test environment than under RAILS_ENV=production.
Under production, one request after warm-up:
Author Load cached=false 20
Author Load cached=true 80
Comment Count cached=false 100
Post Load cached=false 1
Inside an ActionDispatch::IntegrationTest, after clearing the query cache and making exactly one
warm-up request:
query_cache_enabled in the test body: true
Author Load cached=true 100
Comment Count cached=false 100
Post Load cached=false 1
Twenty real author loads became zero, because ActiveRecord::Base.connection_pool.query_cache_enabled
is true for the whole test body rather than per request, so the cache survives from one get to the
next and never sees a cold author. The total query count is 201 either way, which is why a
assert_queries_count style test still passes; what changes is which of them actually hit
PostgreSQL. Measure timings in a process configured like production, and use the test suite for the
count, not for the cost.
What I would run first, and what would change it
Start with the notifications subscriber, every time. It is twelve lines, it costs one block call per
event, it needs no gem in the Gemfile, and on this page it printed Comment Count 20.18 on the
second request, which was the entire answer. Most slow Rails pages are slow for a reason Active
Record already labelled for you, and reaching for a sampling profiler before checking that is
reaching past the answer.
When the subscriber says the database is not the problem, reach for Vernier and read the ERB
annotation, not the top-frames table. The 30 percent overhead is irrelevant when you are looking at
one endpoint on purpose, and being handed the template line is worth more than anything StackProf's
cheaper sampling buys you. Keep StackProf for the case where you need the profile to be nearly free,
or where you want --method on a specific Ruby method and its per-line self time, which is the one
output here that nothing else produces.
Install rack-mini-profiler last, and only if the people who need the numbers are not the people who
can run bin/rails runner. The badge in the corner of the page is a genuinely good interface and it
is 2.53x on the exact kind of page you would install it to diagnose.
What would change this ranking: a Linux host, where StackProf's cpu mode is presumably not the broken thing it is here, and where a cheap cpu-mode profile would be a real second opinion rather than noise. A service already paying for continuous profiling, which makes all of this an after-the-fact confirmation rather than the primary tool. And an endpoint whose time goes into an HTTP call to somebody else's API rather than into PostgreSQL and Ruby, where wall mode is the only mode that says anything at all and the interesting question stops being which line and becomes which service.
What this post does not cover
Production profiling. Nothing above is safe to leave running on a live application, no figure here was taken from one, and continuous profilers, APM agents and the sampling-in-production story are a different post with a different set of constraints. Nothing here was measured under concurrency either: every number is one request at a time, one Puma thread, and a profile taken at 12 concurrent connections has a different shape because contention appears in it.
No YJIT or ZJIT figures, because the Ruby 4.0.5 on this machine is built without both and reports
Ruby was built without YJIT support. No ruby-prof, no derailed_benchmarks, no
ObjectSpace.trace_object_allocations, which is in the memory leak post. No allocation-mode
StackProf, which exists and would have made the allocation section shorter, and which I did not run.
Database-side profiling is absent on purpose: EXPLAIN ANALYZE, pg_stat_statements and index
selection are where you go when the subscriber says one query rather than 201 of them, and the index
measurements for this laptop are in
Rails performance improvements. The sleep_self=5 row in
the cpu-mode table was not chased to its cause; I have the symptom and the timer that produces it,
and not a reading of the Darwin kernel to explain why ITIMER_PROF behaves that way.
Comments
No comments yet. Be the first.