Rails ActiveSupport::Notifications: Custom Instrumentation for Metrics and Production Monitoring

The Rails app had been running for three years when someone finally asked the right question: “Why does saving an order take two seconds?”

It wasn’t the database — pg_stat_statements showed the INSERT completing in 4ms. It wasn’t Puma thread contention. It wasn’t an N+1. The StackProf flamegraph pointed at OrderService#save, a 340-line method that called six other services, four mailers, two third-party webhooks, and a PDF generator.

The problem was that nobody had ever measured any of these individually. The two-second total was one opaque number. Which of those six services was the culprit? Which webhook was timing out?

ActiveSupport::Notifications solved this in about forty lines of code. No extra gem. No agent to install. Nothing to configure. It was already there.

What ActiveSupport::Notifications Is

ActiveSupport::Notifications is Rails’ built-in pub/sub event system. It has been there since Rails 3.0 — so long that most developers forget it exists as a first-class API for their own code.

Rails itself is built on top of it. Every SQL query emits a sql.active_record event. Every controller action emits process_action.action_controller. Every cache hit emits cache_read.active_support. The entire performance data that rack-mini-profiler, New Relic, Datadog, and Skylight consume starts here.

The system has two sides:

1. Instrumenting — emitting an event with a name, a start time, a finish time, and a payload.
2. Subscribing — listening for events by name and doing something when they fire.

Both sides are available to your application code. You can emit custom events from your own service objects, workers, and models, and subscribe to them — or to Rails’ own events — anywhere in the application.

Emitting Custom Events with instrument

The core method is ActiveSupport::Notifications.instrument. Wrap a block, give it a name, optionally add payload data:

class OrderService
  def save(order, params)
    ActiveSupport::Notifications.instrument("save.order_service", order_id: order.id) do
      order.assign_attributes(params)
      order.save!
    end
  end
end

When this runs, subscribers with a matching pattern receive an event object containing:

• :name — "save.order_service"
• :started — the Time the block started
• :finished — the Time it completed
• :duration — finished - started in milliseconds
• :payload — { order_id: order.id }
• :transaction_id — a unique ID shared across nested instrument calls in the same logical operation

The naming convention is action.namespace — lowercase, dot-separated. Rails uses sql.active_record, render_template.action_view, process_action.action_controller. Mirror that for your own events: sync.inventory_service, send.notification_mailer.

You can add data to the payload inside the block:

ActiveSupport::Notifications.instrument("sync.inventory_service", account_id: account.id) do |payload|
  result = InventoryService.sync(account)
  payload[:items_synced] = result.count
  payload[:errors] = result.errors.count
end

The payload block argument gives you a mutable reference. Any subscriber receives items_synced and errors alongside account_id after the block completes.

Instrument calls nest naturally. If OrderService#save calls PdfGenerator#render, which is also instrumented, the inner event fires inside the outer one, and both share the same transaction_id. You can reconstruct the full call tree from a log of events if you record transaction_id alongside each one.

Subscribing to Events

ActiveSupport::Notifications.subscribe("save.order_service") do |name, started, finished, unique_id, payload|
  duration_ms = (finished - started) * 1000
  Rails.logger.info("OrderService#save: #{duration_ms.round(1)}ms order_id=#{payload[:order_id]}")
end

The block receives name, started time, finished time, unique_id, and the payload hash. Set this up in an initializer so it registers once at boot:

# config/initializers/notifications.rb

ActiveSupport::Notifications.subscribe("save.order_service") do |name, started, finished, _, payload|
  duration_ms = ((finished - started) * 1000).round(2)
  Rails.logger.tagged("notifications") do
    Rails.logger.info("#{name} duration_ms=#{duration_ms} order_id=#{payload[:order_id]}")
  end
end

subscribe accepts a string for exact match, a regular expression for pattern matching, or nothing to subscribe to all events:

# Match all events in the order_service namespace
ActiveSupport::Notifications.subscribe(/\.order_service$/) do |name, *args|
  # name could be save.order_service, cancel.order_service, etc.
end

# Match all ActiveRecord SQL events
ActiveSupport::Notifications.subscribe("sql.active_record") do |name, started, finished, _, payload|
  if (finished - started) > 0.1  # >100ms
    Rails.logger.warn("Slow query: #{payload[:sql].squish.truncate(200)}")
  end
end

To unsubscribe, keep a reference to the return value:

subscriber = ActiveSupport::Notifications.subscribe("sync.inventory_service") { |*| ... }
ActiveSupport::Notifications.unsubscribe(subscriber)

This matters in tests. Subscriptions registered globally in initializers persist across tests unless you unsubscribe. Always clean up in teardown or ensure.

Building a Subscriber Class with ActiveSupport::LogSubscriber

For anything beyond a one-liner, ActiveSupport::LogSubscriber is the cleaner pattern. It namespaces your subscription methods, handles the event object properly, and integrates with Rails’ log level filtering:

# app/lib/order_log_subscriber.rb

class OrderLogSubscriber < ActiveSupport::LogSubscriber
  def save(event)
    info do
      "OrderService#save: %.2fms order_id=%d" % [event.duration, event.payload[:order_id]]
    end
  end

  def cancel(event)
    warn do
      "OrderService#cancel: %.2fms order_id=%d reason=%s" % [
        event.duration, event.payload[:order_id], event.payload[:reason]
      ]
    end
  end
end

OrderLogSubscriber.attach_to :order_service

attach_to :order_service subscribes to all events ending in .order_service. The method name matches the event prefix: save.order_service routes to #save, cancel.order_service routes to #cancel. event.duration gives milliseconds directly — no arithmetic needed.

ActiveSupport::LogSubscriber also handles exceptions inside event handlers gracefully — it logs and swallows them rather than letting a broken subscriber affect the request. A bug in your monitoring code should not take down production.

Subscribing to Rails’ Own Events

The same subscription API works for Rails’ internal events. Here are the most useful ones for production monitoring:

# Slow query detector
ActiveSupport::Notifications.subscribe("sql.active_record") do |name, started, finished, _, payload|
  duration_ms = ((finished - started) * 1000).round
  next unless duration_ms > 100

  Rails.logger.warn(
    "slow_query duration_ms=#{duration_ms} " \
    "name=#{payload[:name]} sql=#{payload[:sql].squish.truncate(200)}"
  )
end

# Controller action timing to StatsD
ActiveSupport::Notifications.subscribe("process_action.action_controller") do |name, started, finished, _, payload|
  next if payload[:exception]

  StatsD.timing(
    "rails.controller.duration",
    payload[:duration],
    tags: [
      "controller:#{payload[:controller]}",
      "action:#{payload[:action]}",
      "status:#{payload[:status]}"
    ]
  )
end

# Cache hit/miss ratio
ActiveSupport::Notifications.subscribe(/cache_(read|write|fetch_hit|generate)\.active_support/) do |name, *|
  operation = name.split(".").first.delete_prefix("cache_")
  StatsD.increment("rails.cache.#{operation}")
end

The full list of Rails-emitted events is in the official guides. The most useful for monitoring:

Sending Custom Metrics to Prometheus or StatsD

Wiring ActiveSupport::Notifications to a metrics backend gives you custom application metrics without a full APM agent. Here is a pattern I use with the statsd-instrument gem:

# config/initializers/metrics_subscriber.rb

require "statsd-instrument"

module MetricsSubscriber
  def self.metric_name(event_name)
    parts = event_name.split(".")
    (parts[1..] + [parts[0]]).join(".")
  end

  NAMESPACES = %w[order_service inventory_service payment_processor notification_service].freeze

  NAMESPACES.each do |ns|
    ActiveSupport::Notifications.subscribe(/\.#{ns}$/) do |name, started, finished, _, payload|
      duration_ms = ((finished - started) * 1000).round(2)
      metric = MetricsSubscriber.metric_name(name)

      StatsD.timing("app.#{metric}", duration_ms)
      StatsD.increment("app.#{metric}.count")

      if (error = payload[:exception_object])
        StatsD.increment("app.#{metric}.error", tags: ["error:#{error.class}"])
      end
    end
  end
end

For Prometheus via prometheus_exporter:

# config/initializers/prometheus_subscriber.rb

require "prometheus_exporter/client"

client = PrometheusExporter::Client.default

histogram = client.register(
  :histogram,
  "rails_service_duration_seconds",
  "Duration of Rails service calls",
  buckets: [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5]
)

ActiveSupport::Notifications.subscribe(/\.(order_service|payment_processor)$/) do |name, started, finished, _, payload|
  duration = finished - started
  labels = {
    service:   name.split(".").last,
    operation: name.split(".").first,
    status:    payload[:exception] ? "error" : "success"
  }

  histogram.observe(duration, labels)
end

Both approaches mean your Grafana dashboards get rails_service_duration_seconds{service="payment_processor",operation="charge",status="success"} histograms with p50/p95/p99 percentiles — the same resolution you would get from a commercial APM at a fraction of the cost.

The Order Save Problem, Solved

Back to the two-second order save. Wrapping each service call:

class OrderService
  def save(order, params)
    ActiveSupport::Notifications.instrument("save.order_service", order_id: order.id) do |payload|
      order.assign_attributes(params)
      order.save!

      ActiveSupport::Notifications.instrument("enrich.order_service", order_id: order.id) do
        InventoryService.allocate(order)
      end

      ActiveSupport::Notifications.instrument("notify.order_service", order_id: order.id) do
        NotificationMailer.order_confirmation(order).deliver_later
      end

      ActiveSupport::Notifications.instrument("webhook.order_service",
        order_id: order.id, endpoint: "fulfillment") do
        FulfillmentWebhook.deliver(order)
      end

      ActiveSupport::Notifications.instrument("webhook.order_service",
        order_id: order.id, endpoint: "analytics") do
        AnalyticsWebhook.deliver(order)
      end

      ActiveSupport::Notifications.instrument("pdf.order_service", order_id: order.id) do
        PdfGenerator.order_receipt(order)
      end

      payload[:total_phases] = 5
    end
  end
end

With a logging subscriber attached, the first production order save after deploy produced this:

[notifications] enrich.order_service  duration_ms=12.4   order_id=98234
[notifications] notify.order_service  duration_ms=0.8    order_id=98234
[notifications] webhook.order_service duration_ms=1840.2 order_id=98234 endpoint=fulfillment
[notifications] webhook.order_service duration_ms=3.1    order_id=98234 endpoint=analytics
[notifications] pdf.order_service     duration_ms=83.7   order_id=98234
[notifications] save.order_service    duration_ms=1942.8 order_id=98234

The fulfillment webhook was taking 1.84 seconds on every order. Synchronous HTTP to a vendor with a “best effort” SLA. Moved to a background job. Order save dropped to 110ms. No code rewrite, no architecture change — just measurement followed by one small fix.

Payload Security: Do Not Leak Sensitive Data

The payload is a hash. Whatever you put in it ends up in logs, metrics backends, and every subscriber. After nineteen years of Rails, I have seen user passwords in event payloads because someone included the full params hash, and credit card PANs sitting in log aggregators because someone passed the raw Stripe response.

Treat payloads like you treat logs. Include IDs and counts, not raw values:

# Bad
ActiveSupport::Notifications.instrument("charge.payment_service",
  amount: params[:amount], card_token: params[:card_token], user: current_user) do
  ...
end

# Good
ActiveSupport::Notifications.instrument("charge.payment_service",
  amount_cents: order.amount_cents, user_id: current_user.id) do |payload|
  result = PaymentGateway.charge(...)
  payload[:gateway_response_code] = result.code  # not the full response object
end

If you need richer payload data for development debugging, gate it:

ActiveSupport::Notifications.subscribe("charge.payment_service") do |name, started, finished, _, payload|
  if Rails.env.development?
    Rails.logger.debug("Full payload: #{payload.inspect}")
  else
    Rails.logger.info("charge amount_cents=#{payload[:amount_cents]} user_id=#{payload[:user_id]}")
  end
end

Testing Notification Events

The explicit subscriber pattern works in both Minitest and RSpec and is easy to reason about:

# Minitest
class OrderServiceTest < ActiveSupport::TestCase
  test "instruments save event with order id" do
    events = []
    subscriber = ActiveSupport::Notifications.subscribe("save.order_service") do |name, started, finished, _, payload|
      events << { name: name, payload: payload }
    end

    order = orders(:pending)
    OrderService.new.save(order, { status: "confirmed" })

    assert_equal 1, events.size
    assert_equal order.id, events.first[:payload][:order_id]
  ensure
    ActiveSupport::Notifications.unsubscribe(subscriber)
  end
end

# RSpec
RSpec.describe OrderService do
  around do |example|
    events = []
    sub = ActiveSupport::Notifications.subscribe("save.order_service") do |name, _, _, _, payload|
      events << payload
    end
    @events = events
    example.run
    ActiveSupport::Notifications.unsubscribe(sub)
  end

  it "emits the order_id in the save event" do
    order = create(:order)
    described_class.new.save(order, { status: "confirmed" })
    expect(@events.first).to include(order_id: order.id)
  end
end

Always unsubscribe in ensure or teardown. A leaked subscription accumulates across tests, fires for unrelated events, and produces failures that disappear when you run tests individually — the worst kind of debugging.

A Note on Thread Safety and Subscriber Performance

ActiveSupport::Notifications dispatches synchronously to all subscribers in the instrumenting thread. A slow subscriber makes your instrumented code slower. An exception in a subscriber bubbles up to the caller unless caught inside the subscriber block.

For subscribers that send metrics to a remote endpoint — StatsD, Prometheus — keep them fast: no synchronous HTTP calls inside a subscriber. Both statsd-instrument and prometheus_exporter buffer metrics locally and flush asynchronously by default, which is exactly the right behavior here.

For the OpenTelemetry integration, the opentelemetry-instrumentation-rails gem works exactly like a custom subscriber under the hood — it registers an ActiveSupport::Notifications listener that converts Rails events to OpenTelemetry spans. Your own instrument calls will appear as spans automatically if you wire up a subscriber that creates OpenTelemetry::Trace.current_span.add_event entries.

Using Notifications for Feature Timing Experiments

One pattern I reach for repeatedly: using ActiveSupport::Notifications to time a potential optimization in production before committing to it.

def expensive_report(account)
  if FeatureFlag.enabled?(:optimized_report, account)
    ActiveSupport::Notifications.instrument("report.optimized", account_id: account.id) do
      OptimizedReportQuery.run(account)
    end
  else
    ActiveSupport::Notifications.instrument("report.legacy", account_id: account.id) do
      LegacyReportQuery.run(account)
    end
  end
end

Subscribe to both event names, emit timing to Prometheus, compare p95 latency histograms in Grafana for 24 hours against real traffic, then make the decision. It is a lightweight way to run a timing experiment without instrumenting your test suite or building a full A/B framework — though for something more structured, see the feature flags guide.

FAQ

What is the difference between ActiveSupport::Notifications.subscribe and ActiveSupport::LogSubscriber?

subscribe is the raw API — a block receiving five positional arguments. It works fine for simple metric emissions and one-off subscriptions. ActiveSupport::LogSubscriber is a class-based pattern that subscribes by namespace, routes events to named methods, gives you event.duration directly, and integrates with Rails’ log level filtering and silencing. For anything beyond a quick subscriber, the class-based approach is easier to test and maintain. The two approaches are complementary: use ActiveSupport::LogSubscriber for structured, per-namespace logging, and subscribe blocks in initializers for metric emission.

Does ActiveSupport::Notifications work in background jobs?

Yes, identically. ActiveSupport::Notifications.instrument inside a Sidekiq or Solid Queue job fires the same events and dispatches to the same global subscribers. Since jobs have no HTTP request context, make sure subscribers handle missing request-specific payload keys (like request_id) gracefully — check for nil before using them. A useful pattern is to include a job context hash in every instrument call at the top of perform:

def perform(account_id)
  job_context = { job: self.class.name, account_id: account_id }
  ActiveSupport::Notifications.instrument("process.data_sync_job", **job_context) do
    # work
  end
end

Can I subscribe to notifications from gems and third-party libraries?

Yes, if they use ActiveSupport::Notifications internally. Many popular Rails gems do: faraday with its ActiveSupport integration emits request.faraday, sidekiq-pro emits job lifecycle events, and several mailer gems emit delivery events. Check the gem’s documentation for its event names. Subscribing to third-party events is one of the fastest ways to add external API latency tracking without modifying gem code.

How does ActiveSupport::Notifications relate to OpenTelemetry?

They solve different problems at different levels. ActiveSupport::Notifications is Rails-specific, synchronous, and in-process — it fires events inside your Ruby process and delivers them to subscribers in the same thread. OpenTelemetry is a vendor-neutral distributed tracing standard designed to track requests across service boundaries. The opentelemetry-instrumentation-rails gem bridges them by subscribing to Rails’ built-in ActiveSupport::Notifications events and converting them to OTel spans. For most production Rails apps I run today, the setup is: ActiveSupport::Notifications for fast in-process metrics (StatsD/Prometheus), and OpenTelemetry for distributed tracing across services. Both layers share the same event data from Rails internals.

Your Rails app is a black box in production? TTB Software instruments, monitors, and optimizes production Rails applications. After nineteen years of Rails, we know which metrics matter before a fire starts.