Sijin T V
Sijin T V A passionate Software Engineer who contributes to the wonders happenning on the internet

Using ActiveSupport::Notifications for Advanced App Tracing and Telemetry

Rails instruments almost every meaningful point in the request lifecycle already: SQL execution, view and partial rendering, cache reads, and full controller actions. It publishes all of it on a single internal bus, ActiveSupport::Notifications. Most teams only ever see the log line and forget the bus is there. Turning that bus into metrics costs a few hundred lines of subscriber code and gives you a view of the stack that log parsing can’t: per-controller latencies, cache hit rates, query time distributions, and the render path that made a page slow.

The event bus you already have

Every instrumented call site publishes an event with a name, monotonic start/finish timestamps, and a payload. The ones worth subscribing to:

  • process_action.action_controller carries controller, action, status, format, and pre-computed db_runtime / view_runtime.
  • sql.active_record carries sql, name (SQL, SCHEMA, CACHE, TRANSACTION), cached, and binds.
  • instantiation.active_record fires once per find, with record_count and class_name.
  • render_partial.action_view includes cache_hit, which is how you prove your fragment caches actually work.
  • cache_read.active_support has a hit flag for cache efficiency.

Use monotonic_subscribe so timestamps come from a monotonic clock instead of Time.now, which is subject to wall-clock jumps from NTP.

Subscriber that actually stays out of the way

Subscriptions are synchronous and run in the instrumenting thread. A subscriber that blocks on network I/O will serialize with the request and turn the whole app’s latency into the subscriber’s fault. We learned this the hard way: a subscriber writing to a statsd daemon synchronously with a 5-second timeout sat behind a statsd outage and pushed the API’s p99 from 40 ms to 2.1 s.

Keep subscribers pure aggregation and flush on a fixed cadence:

1
2
3
4
5
6
7
8
ActiveSupport::Notifications.monotonic_subscribe("process_action.action_controller") do |_n, start, finish, _id, payload|
  next if payload[:format] == "*/*"

  labels = [payload[:controller], payload[:action], payload[:status]]
  REQUEST_DURATION.observe(labels, finish - start)
  DB_DURATION.observe(labels, payload[:db_runtime].to_f / 1000.0)
  VIEW_DURATION.observe(labels, payload[:view_runtime].to_f / 1000.0)
end

With prometheus-client, a Histogram with pre-declared label names aggregates server-side, so the subscriber does an array build and a hash insert per event, roughly 2-3 microseconds. The instrumenter itself costs about a microsecond per event. Neither shows up in a p99 that’s measured in milliseconds.

For SQL, filter the noise first. SCHEMA and CACHE events would swamp any dashboard:

1
2
3
4
5
ActiveSupport::Notifications.subscribe("sql.active_record") do |_n, start, finish, _id, payload|
  next if %w[SCHEMA CACHE TRANSACTION].include?(payload[:name])
  table = payload[:sql][/\b(?:from|into|update)\s+(\w+)/i, 1] || "unknown"
  SQL_DURATION.observe([table], finish - start)
end

The cardinality trap

The fastest way to break a metrics pipeline is label cardinality. If you export one series per raw URL or per full query text, Prometheus memory balloons and scrapes start timing out. Normalize at the subscriber: group requests by controller#action, group queries by table and operation, and hash or truncate anything with parameters. Rails already puts prepared-statement values in binds, not in the SQL string, so the raw query text is usually stable; don’t interpolate binds into the string you emit, and never ship parameter values anywhere near logs or exporters. PII in a query label is a compliance incident waiting to happen.

Your own instrumentation points

The same bus instruments code that Rails doesn’t reach. External API calls are the highest-value gap:

1
2
3
ActiveSupport::Notifications.instrument("external_api.request", host: "payments.example.com") do
  http.get("/v1/charges/#{id}")
end

A subscriber groups those by host and status, and you instantly know which downstream service is eating your request budget. This is cheaper and more accurate than trying to infer it from request timings.

On tracing and OpenTelemetry

If you want distributed traces, resist the urge to build directly against an SDK. In mid-2019 the OpenTelemetry project was barely a name and the Ruby SDK was months away from a usable first release; even a year later the API was churning release to release. ActiveSupport::Notifications is the stable contract: write a subscriber that opens and closes spans, then swap the exporter underneath without touching application code. You get vendor independence for free because the instrumented events are already all there.

Production lessons

  • Register subscribers in an initializer, one per concern. Never put subscriptions in models or controllers.
  • Budget: subscribers must stay under ~5 microseconds; anything slower goes on a queue to a background flusher.
  • Filter noise (SCHEMA, CACHE, TRANSACTION) and normalize labels before you emit, or the dashboard is unreadable.
  • Measure the overhead in staging before enabling in production; expect under 0.5% throughput impact, not zero.
  • Scope subscriptions in tests with a teardown, or your test suite absorbs every event in the app.

Telemetry only pays off if it’s boring to maintain. ActiveSupport::Notifications gives you that because the interface is stable and the semantics are already battle-tested inside Rails itself.

comments powered by Disqus