Rails logs measure the controller. They don’t measure the queue, the auth middleware, the rate limiter, or the request as the client actually experienced it. That gap is exactly where latency hides: a request can spend 200 ms waiting in a Puma queue before Rails even wakes up, and the log line will report 40 ms of controller time as if nothing happened. The fix is to measure at the outermost layer of the Rack stack, where the web server hands the request off, and that means a piece of custom middleware.

The Rack contract, done right

A Rack middleware is a function from env to [status, headers, body]. The naive version measures @app.call, and it misses two things. First, the body is lazy: for streaming responses (SSE, chunked downloads) the interesting time is spent in body.each, after call returns. Second, body can be a hijacked or rack.after_reply-driven response where timing the synchronous call is meaningless. For the common JSON API case, timing call plus a streaming-aware body wrapper is the honest measurement:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
class RequestTelemetry
  REQUEST_DURATION = Prometheus::Client::Histogram.new(
    name: :http_request_duration_seconds,
    docstring: "Total request duration",
    labels: %i[method status route],
    buckets: [0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5]
  )

  def initialize(app, registry:)
    @app = app
    registry.register(REQUEST_DURATION)
  end

  def call(env)
    started = Process.clock_gettime(Process::CLOCK_MONOTONIC)
    status, headers, body = @app.call(env)
    duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started
    route = route_for(env)
    REQUEST_DURATION.observe([env["REQUEST_METHOD"], status.to_s, route], duration)
    [status, headers, wrap_body(body, started, route)]
  end

  private

  def route_for(env)
    params = env["action_dispatch.request.path_parameters"]
    return "unrouted" unless params
    "#{params[:controller]}##{params[:action]}"
  end

  def wrap_body(body, _started, _route)
    # Rails responses respond to each/close; passing through keeps streaming intact
    body
  end
end

Insert it at the top of the stack so it measures true ingress, before Rails’ own middleware runs:

1
Rails.application.config.middleware.insert_before 0, RequestTelemetry

Reading action_dispatch.request.path_parameters after @app.call returns is the trick that makes route labels work: routing hasn’t run yet when the middleware starts, but by the time the response comes back the params are populated. That gives you orders#show instead of /orders/12345, which is the difference between a useful dashboard and a cardinality bomb.

The cardinality discipline

[method, status, route] is a small, bounded label set, and it stays that way only if you never let a dynamic value in. No request IDs, no user IDs, no raw paths. We once saw a teammate add path as a label “temporarily” and the scrape became a memory leak within a week: every distinct URL became a series, and the Prometheus node’s RSS doubled before anyone looked at it. Normalize first, emit second.

Allocation is the other hidden tax. The Histogram#observe path does an array and a hash lookup; at 5k requests/second per host that’s noise. What isn’t noise is string-building in the hot path, so reuse label values and avoid to_s on things that are already strings. Keep the middleware to a handful of microseconds; if it ever shows up in its own profile, it’s too fat.

Exceptions, and why they must re-raise

Rack middleware sits below the Rails exception handling. If your middleware raises, the web server process can crash or respond with a raw 500 that never touches your logs. Record, then re-raise, so the failure is visible in your metrics and still propagates normally:

1
2
3
4
rescue StandardError => e
  REQUEST_ERRORS.increment(labels: { route: route_for(env), class: e.class.name })
  raise
end

A middleware that turns an outage into a silent 500 is worse than no middleware at all.

The OpenTelemetry hook

As of late 2020 the OpenTelemetry Ruby SDK is still pre-1.0 and the API churns between releases, so don’t let it leak through your application. The clean seam is the same one: a subscriber or an env-injected tracer that your middleware calls behind an abstraction. Start Prometheus-only if you want to ship today, and add span creation behind that seam later; the ActiveSupport::Notifications bus is a second, equally good place to open spans. The point of the middleware isn’t the exporter — it’s that you own one measurement point for the whole request lifecycle, and every future system hooks in there instead of scattering timing calls through controllers.

Production lessons

• Measure at the outermost layer, grouped by controller#action, never by path.
• Never block on the exporter in the request thread. Aggregate in-process and flush on a timer, or hand events to a queue with a bounded size and a drop policy.
• Rescue and re-raise; your middleware must not be a new way to take down the server.
• Watch label cardinality and allocation; telemetry that needs its own p99 dashboard is too expensive.
• insert_before 0 is your friend for ingress timing; anything that needs env mutations runs below you.