Rails monitoring, and the 645 ms it does not measure

A production Rails application will tell you, without being asked, that its median request took 63 milliseconds. That number can be exactly right and the people using the site can be waiting 787 milliseconds for the same page, at the same second, on the same machine. Here is that pair, measured twice against one worker and one thread with /usr/sbin/ab:

ab -n 240 -c 1
  ab:     mean 81.965 ms   p50 83 ms
  Rails:  mean 80.1 ms     p50 81 ms   p95 111 ms

ab -n 240 -c 12
  ab:     mean 779 ms      p50 787 ms  p95 948 ms
  Rails:  mean 65.5 ms     p50 63 ms   p95 84 ms   max 237 ms

The Rails line is the Completed 200 OK in NNNms from the application's own log, which is process_action.action_controller, which is what every APM agent and every dashboard on the market is reading. It did not get slower under load. It got faster, because the process warmed up. Every graph built on it says the application is healthy while the site is unusable.

Conditions, because a number without them is not checkable: Apple M2 Max, 12 cores, macOS arm64-darwin25, Ruby 4.0.5, Rails 8.1.3.1, Puma 8.0.2, PostgreSQL 17.7 on port 15432, ApacheBench 2.3. The application is this site running RAILS_ENV=production locally against a scratch database, WEB_CONCURRENCY=1 RAILS_MAX_THREADS=1, requesting /yield/rails-time-zones, a 70 kB rendered Markdown article. Everything below was run in that setup unless it says otherwise.

What Rails measures, exactly

One warm request through the real application emitted 25 notifications:

   12  render_partial.action_view
    7  sql.active_record
    1  start_processing.action_controller
    1  instantiation.active_record
    1  render_template.action_view
    1  render_layout.action_view
    1  process_action.action_controller
    1  request.action_dispatch

The one that matters is process_action.action_controller, and its payload has 14 keys:

[:action, :cached_queries_count, :controller, :db_runtime, :format, :headers, :method,
 :params, :path, :queries_count, :request, :response, :status, :view_runtime]

request is the live ActionDispatch::Request, which is the hook you need later. queries_count and cached_queries_count are the two fields worth an alert on their own, for the reason N+1 queries in Rails goes into: a request whose query count scales with its row count is a bug you can catch with a threshold and cannot catch with a regex over prose.

Now the part that decides what a dashboard built on this is worth. One request produces seven measurements of itself, they nest inside each other, and they are not the same number:

  render_layout.action_view                    8.54 ms
  process_action.action_controller            47.71 ms
  request.action_dispatch                     48.31 ms
  view_runtime (payload)                       7.72 ms
  db_runtime (payload)                         2.55 ms
  queries_count (payload)                         7
  x-runtime header                            48.288 ms

view_runtime plus db_runtime is 10.27 ms of a 47.71 ms request. The two numbers that appear in every Rails performance monitoring screenshot ever taken cover just under 22 percent of this one. The other 78 percent is controller code, and on this page most of it is Yield::Repository.find reading and YAML-parsing every Markdown file in app/content/yield, which is the subject of Rails performance improvements. Nothing in the framework's instrumentation points at it. You get a request duration and a database subtotal, and the difference between them is a single undifferentiated lump.

x-runtime is Rack::Runtime, it sits outside process_action, and at 48.288 ms against 48.31 ms for request.action_dispatch the middleware stack below Rack::Runtime costs essentially nothing on this request. That is the outermost thing Rails knows about. It is still inside the process.

The number nobody in the stack is measuring

Queue time is how long the request sat in the socket backlog before a Puma thread picked it up. It is the difference between the two columns at the top of this page, it is the first thing that moves when an application is in trouble, and no part of Rails computes it.

I grepped for it rather than trusting that:

$ grep -rl "X-Request-Start\|HTTP_X_REQUEST_START" \
    actionpack-8.1.3.1 activesupport-8.1.3.1 railties-8.1.3.1 puma-8.0.2
puma-8.0.2/docs/deployment.md

One hit, in a documentation file. What it says, at docs/deployment.md:88:

* Have your upstream proxy set a header with the time it received the request:
    * nginx: `proxy_set_header X-Request-Start "${msec}";`
    * haproxy >= 1.9: `http-request set-header X-Request-Start
      t=%[date()]%[date_us()]`
    * haproxy < 1.9: `http-request set-header X-Request-Start t=%[date()]`
* In your Rack middleware, determine the amount of time elapsed since
  `X-Request-Start`.
* To improve accuracy, you will want to subtract time spent waiting for slow
  clients:
    * `env['puma.request_body_wait']` contains the number of milliseconds Puma
      spent waiting for the client to send the request body.
    * haproxy: `%Th` (TLS handshake time) and `%Ti` (idle time before request)
      can also be added as headers.

"In your Rack middleware" is the whole situation. The server knows the answer is important enough to document; the framework ships nothing; the vendors sell it as the headline feature of the product. Here is the middleware, which handles both header formats because nginx and haproxy disagree:

class QueueTime
  HEADER = "HTTP_X_REQUEST_START"

  def initialize(app)
    @app = app
  end

  def call(env)
    if (raw = env[HEADER])
      # nginx sends "1790000000.123"; haproxy sends "t=1790000000123456".
      started = raw.delete_prefix("t=").to_f
      started /= 1_000_000 if started > 1_000_000_000_000
      queue_ms = (Time.now.to_f - started) * 1000
      queue_ms -= env["puma.request_body_wait"].to_f
      env["queue_time_ms"] = queue_ms.round(2)
    end
    @app.call(env)
  end
end

To measure it rather than assert it I ran it as a bare Rack application under Puma 8.0.2 with one thread, serving a handler that burns 60 ms of CPU and returns 70 kB, driven by a Ruby client that stamps X-Request-Start in nginx's format on every request the way nginx would. Two runs, the same process:

=== concurrency 1, 40 requests, one Puma thread
client total: n=40 mean=61.7 p50=61.4 p95=64.6 max=65.7
server: n=40 negative=4 queue_mean=0.60 queue_p50=0.54 queue_p95=1.83 queue_max=2.43 | app_mean=60.01

=== concurrency 12, 20 requests per thread, one Puma thread
client total: n=240 mean=705.1 p50=722.6 p95=734.5 max=843.1
server: n=240 negative=0 queue_mean=644.72 queue_p50=662.29 queue_p95=674.24 queue_max=782.31 | app_mean=60.00

644.72 plus 60.00 is 704.72 against a client-observed 705.1. The arithmetic closes. The application's own measurement is a flat 60.00 ms in both runs, correct in both runs, and blind to 91 percent of what the twelfth client experienced.

Wire it into a real Rails application and the request line has everything in it. This is the actual output, one subscriber and the middleware above wrapped around this site's own stack, the second request given a header 400 ms in the past:

{"action":"YieldController#show","status":200,"app_ms":46.73,"queue_ms":0.49,"db_ms":2.2,"queries":7}
{"action":"YieldController#show","status":200,"app_ms":46.81,"queue_ms":400.09,"db_ms":2.44,"queries":7}

ActiveSupport::Notifications.monotonic_subscribe("process_action.action_controller") do |_, start, finish, _, payload|
  $stdout.puts JSON.generate(
    action: "#{payload[:controller]}##{payload[:action]}",
    status: payload[:status],
    app_ms: ((finish - start) * 1000).round(2),
    queue_ms: payload[:request].env["queue_time_ms"],
    db_ms: payload[:db_runtime]&.round(2),
    queries: payload[:queries_count]
  )
end

That is the whole of rails queue time monitoring: one middleware, one subscriber, and an nginx directive. Alert on the p95 of queue_ms, not on its mean, and not on app_ms at all.

The dead end: it goes negative

The first thing the middleware printed at low concurrency was this.

queue=-0.25 app=60.0
queue=0.19 app=60.0
queue=-0.35 app=60.0

4 of 40 requests reported a negative queue time on an idle server. The cause is in the nginx directive itself: ${msec} is seconds with three decimal places, so the proxy's timestamp is rounded to the nearest millisecond and can round up to half a millisecond into the future. Subtract it from Time.now and you get a negative interval.

This is worth knowing for two reasons. Below about 2 ms the metric is noise and you should not draw it, let alone alert on it, which is fine because a queue time you care about is in the hundreds of milliseconds. And on a real deployment the proxy and the application are two hosts with two clocks, so any skew between them lands directly and permanently in this metric with no way to tell it from a real queue. My load generator and my server were the same machine and the error was still visible. Treat a persistently negative queue time as a clock problem, not as a fast application.

Puma knows it is saturated and nothing asks it

While that c=12 run was going, Puma.stats:

{"started_at":"2026-09-27T15:18:53Z","backlog":11,"running":1,"pool_capacity":0,"busy_threads":12,
 "io_threads":0,"backlog_max":11,"max_threads":1,"requests_count":60,"reactor_max":3,
 "versions":{"puma":"8.0.2","ruby":{"engine":"ruby","version":"4.0.5","patchlevel":0}}}

pool_capacity is 0. That is the alarm, and it is the one metric in this article that requires no arithmetic: a worker with no capacity left is a worker whose next request queues. busy_threads is 12 against max_threads 1, which looks wrong until you read the definition at puma-8.0.2/lib/puma/thread_pool.rb:150, @spawned - @waiting + @todo.size. It counts the backlog, so it can exceed the thread count and is not the number you want.

One trap, four lines above that:

def stats
  with_mutex do
    temp = @backlog_max
    @backlog_max = 0

Reading the stats resets the peak. Two things polling Puma.stats will each see roughly half the spikes and neither will see the real maximum. Poll it from exactly one place.

Getting at it in a web process means activate_control_app in config/puma.rb or a route that calls Puma.stats, which is a string of JSON, not a Hash.

Notifications has three subscriber shapes and they cost different amounts

ActiveSupport::Notifications is the entire monitoring API. Everything else is a consumer of it. There are three ways to attach, they are not interchangeable, and the difference is not stylistic.

ActiveSupport::Notifications.subscribe(name) { |name, start, finish, id, payload| }
ActiveSupport::Notifications.monotonic_subscribe(name) { |name, start, finish, id, payload| }
ActiveSupport::Notifications.subscribe(name) { |event| }

Printed from a live run: the first yields Time objects, the second yields Float monotonic clock readings, the third yields an ActiveSupport::Notifications::Event. Use subscribe with five arguments and you are computing a duration by subtracting two wall clock times, which is the wrong clock for an interval on a machine that runs NTP.

The Event shape is the expensive one and it is the one that pays. From one real article render:

  event.duration     50.33
  event.cpu_time     49.06
  event.idle_time    1.27
  event.allocations  42007
  event.gc_time      0.0

1.27 ms of idle time out of 50.33 means this request was not waiting on anything; it was burning CPU. That single distinction is most of what you want monitoring for, it decides whether more threads will help or hurt, and the five-argument block cannot give it to you at any price. 42,007 allocations for one page is the other half of the same answer.

The cost, 200,000 calls each, same process:

bare block, no instrument                          0.041 us/call
instrument, nobody listening                       0.205 us/call
instrument, one monotonic subscriber               1.551 us/call
instrument, one 5-arg block subscriber             1.668 us/call
instrument, one Event-object subscriber            2.374 us/call

Against a 47 ms request, one Event subscriber on process_action is 0.005 percent. Against sql.active_record on a request that runs 200 queries it is 0.47 ms, still nothing. The number that would matter is instrumenting something inside a loop that runs a million times, and the framework does not do that anywhere.

The dead end: instrument is not free in development

My first run of that benchmark, in the development environment, measured instrument with no subscribers at 2.454 us and I wrote down that the no-subscriber fast path does not work. It works. What does not work is testing it in development:

RAILS_ENV=development  server_timing=true
listening?("custom.metric") = true

ActiveSupport::Notifications.instrument checks notifier.listening?(name) and skips the whole handle if nothing is attached. ActionDispatch::ServerTiming, which config.server_timing = true puts in the development stack, subscribes to the regular expression /\A[^!]/ at server_timing.rb:36. That matches every event name that does not start with !. So in development listening? is true for every string you will ever pass, including event names invented five minutes ago that nothing consumes, and every instrument call in the application pays full price. ActionDispatch::ServerTiming.unsubscribe in the same process took it back to 0.205 us.

This matters beyond a benchmark: if you turn server_timing on in production to debug something, you have just attached a subscriber to every event in the process, including your own custom ones.

A subscriber that raises takes the request with it

This is the failure mode of ruby on rails monitoring code that nobody expects, because the mental model is that instrumentation is a side channel. It is not. It runs inline, on the request thread, inside ensure.

ONE subscriber raising    -> ArgumentError: monitoring blew up
TWO subscribers, one raising -> ArgumentError: monitoring blew up
THREE subscribers, two raising -> ActiveSupport::Notifications::InstrumentationSubscriberError:
    Exception(s) occurred within instrumentation subscribers: ArgumentError, TypeError
block ran before the subscriber raised: true

The asymmetry is deliberate and is worth reading, at activesupport-8.1.3.1/lib/active_support/notifications/fanout.rb:20:

def iterate_guarding_exceptions(collection, &block)
  case collection.size
  when 0
  when 1
    collection.each(&block)
  else
    exceptions = nil
    collection.each do |s|
      yield s
    rescue Exception => e
      exceptions ||= []
      exceptions << e
    end

With exactly one listener there is no rescue at all, for speed. With two or more the exceptions are collected, and then re-raised anyway: one of them bare, several of them wrapped in InstrumentationSubscriberError. There is no configuration under which a raising subscriber is swallowed.

So a metrics subscriber that does payload[:user].id on the one request where user is nil returns a 500 for a page that rendered perfectly. The work was already done, block ran before the subscriber raised: true, and the response is thrown away on the way out. Wrap the body of every subscriber you write in a rescue StandardError that reports through the error reporter and returns, or accept that your monitoring is now a source of outages.

Server-Timing, briefly

Rails ships a per-request profiler and turns it off in production. config.server_timing = true in config/environments/development.rb adds ActionDispatch::ServerTiming, which puts this in the response headers, readable in the browser's network panel:

start_processing.action_controller;dur=0.00
sql.active_record;dur=1.94
instantiation.active_record;dur=0.03
render_partial.action_view;dur=4.03
render_template.action_view;dur=6.95
render_layout.action_view;dur=10.65
process_action.action_controller;dur=62.12

Do not add those up. server_timing.rb:66 groups events by name and sums each group, and the events nest: process_action contains render_layout contains render_template contains the three render_partial calls. The 4.03 is counted four times over. It is a tree flattened into a list with the tree structure thrown away, so the only line you can read on its own is the outermost one, and the only way to find where a request went is to know which name contains which.

In production the default is false (railties-8.1.3.1/lib/rails/application/configuration.rb:85) and the header is absent. Verified by curl: x-request-id and x-runtime are there, server-timing is not.

The smallest thing that is monitoring rather than logging

Percentiles, per action, in process. This ran against 80 real requests through this site:

ActiveSupport::Notifications.monotonic_subscribe("process_action.action_controller") do |_, start, finish, _, payload|
  Latency.record("#{payload[:controller]}##{payload[:action]}", (finish - start) * 1000)
end

YieldController#show     n=60   p50=  48.0 p95=  55.8 p99= 273.2 max= 273.2
YieldController#index    n=20   p50=  51.3 p95=  55.7 p99=  55.7 max=  55.7

p50 48.0 and p99 273.2 on the same action, on an idle machine, with no load and no slow query. The tail is the first request, before anything was warm. A mean over those 60 sits a couple of milliseconds above the median and hides the 273 entirely, which is what a mean is for.

The cost of keeping every duration in an array, which is what that collector does, is 7.6 MB per million requests per process: ObjectSpace.memsize_of on an Array of 1,000,000 Float objects is 8,000,040 bytes, and it never shrinks. So it has to be reset on a schedule, or bounded, or replaced by a real histogram with fixed buckets. And it is per process: eight Puma workers hold eight disjoint samples, and the p95 of the union is not the maximum of the eight p95s. This is the point at which a prometheus_exporter process or a hosted agent stops being an indulgence, and it arrives earlier than people expect.

What to buy, and when

The position: build queue time and buy error tracking. Queue time is 20 lines and one nginx directive, it is the metric that actually tells you the application is in trouble, and no vendor can compute it for you anyway since it needs a header your proxy has to set. Error tracking is the opposite: grouping, deduplication, release tracking and notification are a real product, and the version of it you write yourself is a table of backtraces nobody opens.

What would change my mind on the first half: a team with more than a handful of services, where the value is one place to correlate them rather than the numbers themselves.

Most lists of rails monitoring tools are a paragraph of adjectives per vendor and no versions, which is the half that goes stale. Here are the versions instead, read off the rubygems.org API on 2026-09-27, because a rails apm recommendation with a dead gem in it is worthless.

gem	version	released	licence
sentry-rails	7.0.0	2026-09-01	MIT
newrelic_rpm	10.8.0	2026-09-14	Apache-2.0
datadog	2.43.0	2026-09-22	BSD-3-Clause, Apache-2.0
appsignal	4.10.4	2026-09-22	MIT
skylight	7.1.1	2026-04-17	Nonstandard
prometheus_exporter	2.3.1	2025-11-12	MIT
yabeda-rails	0.11.0	2025-12-03	MIT
stackprof	0.2.28	2026-02-13	MIT
vernier	1.11.0	2026-08-17	MIT
rack-mini-profiler	5.0.0	2026-08-21	MIT

That is the whole of what I can tell you about them, because I did not install one of them. What each subscribes to and whether it reads a proxy header is a claim about somebody else's code, and this page only carries claims it ran. The last four in that table are not monitoring at all: they are profilers you reach for once a graph has already told you which endpoint to open.

What this page does not cover

Nothing about /up and what a green health check does and does not prove, which is Rails health checks. Nothing about log formatting or Rails.event, which is structured logging in Rails 8.1. Nothing about Rails.error and exception reporting, which is error handling in Rails. No job monitoring: Active Job emits its own event set and Solid Queue has its own tables, and neither appears above. No database-side monitoring, no pg_stat_statements, no connection pool metrics. No distributed tracing and no span propagation across services, which is a different problem with a different answer. No alerting, no on-call, no dashboards: this is about where the numbers come from, not what to do when one of them moves.

And every figure here is one laptop, one worker, one thread. The shape generalises, the milliseconds do not.