Rails ActiveSupport::Notifications: Aangepaste Instrumentatie voor Metrics en Productie-monitoring

De Rails-applicatie draaide al drie jaar toen iemand eindelijk de juiste vraag stelde: “Waarom duurt het opslaan van een order twee seconden?”

Het was niet de database — pg_stat_statements liet zien dat de INSERT in 4ms klaar was. Geen Puma-thread contention. Geen N+1. De StackProf-flamegraph wees naar OrderService#save, een methode van 340 regels die zes andere services aanriep, vier mailers, twee externe webhooks en een PDF-generator.

Het probleem was dat niemand ooit iets van die onderdelen apart had gemeten. De twee seconden waren één ondoorzichtig getal. Welke van die zes services was de boosdoener? Welke webhook liep vast?

ActiveSupport::Notifications loste dit op in ongeveer veertig regels code. Geen extra gem. Geen agent om te installeren. Niets te configureren. Het was er al.

Wat ActiveSupport::Notifications Is

ActiveSupport::Notifications is het ingebouwde pub/sub-eventsysteem van Rails. Het bestaat al sinds Rails 3.0 — zo lang dat de meeste ontwikkelaars vergeten dat het een volwaardig API is voor hun eigen code.

Rails zelf is erop gebouwd. Elke SQL-query stuurt een sql.active_record-event. Elke controlleractie stuurt process_action.action_controller. Elke cache-hit stuurt cache_read.active_support. Alle prestatiedata die rack-mini-profiler, New Relic, Datadog en Skylight verbruiken, begint hier.

Het systeem heeft twee kanten:

1. Instrumenteren — een event uitsturen met een naam, begintijd, eindtijd en payload.
2. Abonneren — luisteren naar events op naam en actie ondernemen wanneer ze binnenkomen.

Beide kanten zijn beschikbaar voor je eigen applicatiecode. Je kunt aangepaste events versturen vanuit je eigen service-objecten, workers en models, en je kunt erop abonneren — of op events van Rails zelf — overal in de applicatie.

Aangepaste Events Versturen met instrument

De kernmethode is ActiveSupport::Notifications.instrument. Wikkel een blok, geef het een naam en voeg optioneel payload-data toe:

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

Wanneer dit draait, ontvangen abonnees met een overeenkomend patroon een event-object met:

• :name — "save.order_service"
• :started — het tijdstip waarop het blok begon
• :finished — het tijdstip waarop het klaar was
• :duration — finished - started in milliseconden
• :payload — { order_id: order.id }
• :transaction_id — een uniek ID dat gedeeld wordt door geneste instrument-aanroepen in dezelfde logische operatie

De naamgevingsconventie is actie.namespace — kleine letters, punt als scheidingsteken. Rails gebruikt sql.active_record, render_template.action_view, process_action.action_controller. Gebruik hetzelfde patroon voor je eigen events: sync.inventory_service, send.notification_mailer.

Je kunt data aan de payload toevoegen binnen het blok:

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

Het payload-blokargument is een muteerbare referentie. Elke abonnee ontvangt items_synced en errors naast account_id nadat het blok klaar is.

instrument-aanroepen nesten vanzelf. Als OrderService#save PdfGenerator#render aanroept, dat ook geïnstrumenteerd is, vuurt het binnenste event binnen het buitenste, en beide delen dezelfde transaction_id. Je kunt de volledige aanroepboom reconstrueren uit een log van events als je transaction_id bij elk event bijhoudt.

Abonneren op 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

Het blok ontvangt naam, begintijd, eindtijd, unique_id en de payload-hash. Stel dit in in een initializer zodat het eenmalig bij opstarten wordt geregistreerd:

# 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 accepteert een string voor exacte match, een reguliere expressie voor patroonmatching, of niets om op alle events te abonneren:

# Alle events in de order_service-namespace
ActiveSupport::Notifications.subscribe(/\.order_service$/) do |name, *args|
  # name kan save.order_service, cancel.order_service etc. zijn
end

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

Om te de-abonneren, bewaar je de referentie naar de returnwaarde:

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

Dit is belangrijk in tests. Subscriptions die globaal in initializers zijn geregistreerd, blijven actief over tests heen. Zorg altijd voor opschoning in teardown of ensure.

Een Abonneeklasse Bouwen met ActiveSupport::LogSubscriber

Voor alles wat meer is dan een oneliner is ActiveSupport::LogSubscriber het schonere patroon. Het namespacet je abonneemethoden, verwerkt het event-object correct en integreert met het logfiltermechanisme van Rails:

# 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 reden=%s" % [
        event.duration, event.payload[:order_id], event.payload[:reason]
      ]
    end
  end
end

OrderLogSubscriber.attach_to :order_service

attach_to :order_service abonneert op alle events die eindigen op .order_service. De methodenaam komt overeen met het event-prefix: save.order_service gaat naar #save, cancel.order_service naar #cancel. event.duration geeft milliseconden direct terug — geen berekeningen nodig.

ActiveSupport::LogSubscriber vangt ook uitzonderingen binnen event-handlers netjes op — het logt en slikt ze in plaats van een kapotte abonnee de applicatie te laten beïnvloeden.

Abonneren op Rails’ Eigen Events

Hetzelfde subscription-API werkt voor de interne events van Rails. De meest nuttige voor productie-monitoring:

# Detector voor trage queries
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(
    "trage_query duration_ms=#{duration_ms} " \
    "name=#{payload[:name]} sql=#{payload[:sql].squish.truncate(200)}"
  )
end

# Timing van controlleracties naar 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-trefferverhouding
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

De meest nuttige events voor monitoring:

Aangepaste Metrics Sturen naar Prometheus of StatsD

ActiveSupport::Notifications koppelen aan een metrics-backend geeft je aangepaste applicatiemetrics zonder een volledig APM-agent. Een patroon dat ik gebruik met de 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

Voor 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",
  "Duur van Rails service-aanroepen",
  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

Beide aanpakken geven je Grafana-dashboards met rails_service_duration_seconds{service="payment_processor",operation="charge",status="success"}-histogrammen inclusief p50/p95/p99-percentielen — dezelfde resolutie als een commerciële APM voor een fractie van de kosten.

Het Order-opslaan Probleem, Opgelost

Terug naar het twee seconden durende order-opslaan. Elke service-aanroep in een instrument wikkel:

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

Met een log-abonnee actief gaf de eerste productie-order na de deploy dit:

[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

De fulfillment-webhook duurde 1,84 seconden per order. Een synchrone HTTP-aanroep naar een leverancier met een “best effort”-SLA. Naar een achtergrondtaak verplaatst. Het order-opslaan daalde naar 110ms. Geen grote refactoring, geen architectuurwijziging — gewoon meten, gevolgd door één kleine aanpassing.

Payload-beveiliging: Laat Geen Gevoelige Data Lekken

De payload is een hash. Wat je er ook in stopt, het komt terecht in logs, metrics-backends en bij elke abonnee. Na negentien jaar Rails heb ik wachtwoorden in event-payloads gezien doordat iemand de volledige params-hash meestuurde, en creditcard-nummers in log-aggregators doordat iemand het ruwe Stripe-antwoord doorgaf.

Behandel payloads zoals je logs behandelt. Stuur ID’s en aantallen mee, niet ruwe waarden:

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

# Goed
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  # niet het volledige antwoordobject
end

Als je rijkere payload-data nodig hebt voor ontwikkeldebugging, begrens dat dan:

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

Notification-events Testen

Het expliciete abonneepatroon werkt in zowel Minitest als RSpec en is eenvoudig te begrijpen:

# Minitest
class OrderServiceTest < ActiveSupport::TestCase
  test "instrumenteert save-event met 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 "stuurt het order_id mee in het save-event" do
    order = create(:order)
    described_class.new.save(order, { status: "confirmed" })
    expect(@events.first).to include(order_id: order.id)
  end
end

Zorg altijd voor de-abonneren in ensure of teardown. Een gelekte subscription accumuleert over tests heen, vuurt voor niet-gerelateerde events en produceert mislukkingen die verdwijnen wanneer je tests afzonderlijk uitvoert — het slechtst denkbare debuggingprobleem.

Een Opmerking over Thread-veiligheid en Abonneeprestaties

ActiveSupport::Notifications verzendt synchroon naar alle abonnees in de instrumenterende thread. Een trage abonnee maakt je geïnstrumenteerde code trager. Een uitzondering in een abonnee werkt door naar de aanroeper tenzij deze wordt opgevangen in het abonneeblok.

Voor abonnees die metrics versturen naar een extern eindpunt — StatsD, Prometheus — houd ze snel: geen synchrone HTTP-aanroepen in een abonnee. Zowel statsd-instrument als prometheus_exporter bufferen metrics lokaal en flushen asynchroon standaard, wat precies het juiste gedrag is.

Voor de OpenTelemetry-integratie werkt de opentelemetry-instrumentation-rails-gem precies als een aangepaste abonnee — het registreert een ActiveSupport::Notifications-luisteraar die Rails-events omzet naar OpenTelemetry-spans. Je eigen instrument-aanroepen verschijnen automatisch als spans als je een abonnee aanmaakt die OpenTelemetry::Trace.current_span.add_event-invoeren aanmaakt.

Notifications Gebruiken voor Timingexperimenten

Een patroon waar ik regelmatig naar teruggrijp: ActiveSupport::Notifications gebruiken om een potentiële optimalisatie te timen in productie voordat ik de definitieve keuze maak.

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

Abonneer op beide event-namen, stuur timing naar Prometheus, vergelijk p95-latentie-histogrammen in Grafana gedurende 24 uur op echt verkeer, en neem dan de beslissing. Een lichtgewicht manier om een timingexperiment uit te voeren zonder een volledige A/B-framework te bouwen — hoewel je voor iets gestructureerder de feature flags-gids kunt raadplegen.

Veelgestelde Vragen

Wat is het verschil tussen ActiveSupport::Notifications.subscribe en ActiveSupport::LogSubscriber?

subscribe is de ruwe API — een blok dat vijf positionele argumenten ontvangt. Prima voor eenvoudige metrics-emissie en eenmalige subscriptions. ActiveSupport::LogSubscriber is een klassegebaseerd patroon dat per namespace abonneert, events naar benoemde methoden routeert, event.duration direct geeft, en integreert met het loglevelfilteringmechanisme van Rails. Voor alles wat meer is dan een snelle abonnee is de klassegebaseerde aanpak gemakkelijker te testen en te onderhouden.

Werkt ActiveSupport::Notifications in achtergrondtaken?

Ja, identiek. ActiveSupport::Notifications.instrument in een Sidekiq- of Solid Queue-taak stuurt dezelfde events en levert ze af aan dezelfde globale abonnees. Omdat taken geen HTTP-verzoekcontext hebben, zorg je er voor dat abonnees ontbrekende verzoek-specifieke payload-sleutels (zoals request_id) netjes afhandelen. Een nuttig patroon is het meesturen van een taakcontext-hash in elke instrument-aanroep bovenaan 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
    # werk
  end
end

Kan ik abonneren op notifications van gems en externe bibliotheken?

Ja, als ze intern ActiveSupport::Notifications gebruiken. Veel populaire Rails-gems doen dit: faraday met zijn ActiveSupport-integratie stuurt request.faraday, sidekiq-pro stuurt taaklevenscyclus-events, en diverse mailer-gems sturen bezorgingsevents. Controleer de documentatie van de gem voor de event-namen. Abonneren op events van derden is een van de snelste manieren om latentietracking voor externe API’s toe te voegen zonder de gem-code te wijzigen.

Hoe verhoudt ActiveSupport::Notifications zich tot OpenTelemetry?

Ze lossen verschillende problemen op op verschillende niveaus. ActiveSupport::Notifications is Rails-specifiek, synchroon en in-process — het vuurt events binnen je Ruby-proces en levert ze af aan abonnees in dezelfde thread. OpenTelemetry is een leveranciersneutrale gedistribueerde tracing-standaard die verzoeken over servicegrenzen heen volgt. De opentelemetry-instrumentation-rails-gem verbindt ze door te abonneren op Rails’ ingebouwde ActiveSupport::Notifications-events en ze om te zetten naar OTel-spans. Voor de meeste productie-Rails-applicaties die ik vandaag beheer is de opzet: ActiveSupport::Notifications voor snelle in-process metrics (StatsD/Prometheus) en OpenTelemetry voor gedistribueerde tracing over services heen.

Je Rails-applicatie is een zwarte doos in productie? TTB Software instrumenteert, bewaakt en optimaliseert productie-Rails-applicaties. Na negentien jaar Rails weten we welke metrics er toe doen vóórdat er brand uitbreekt.