Rails StackProf: Flamegraph CPU-profilering voor Ruby-productieapplicaties

Het /reports-endpoint nam elf seconden in beslag. Sentry wist dat, op de manier waarop Sentry dingen weet — een brede kwast, geen details. ActiveRecord: 9,2 seconden. Dat was de volledige vermelding. Geen methodenamen, geen regelnummers, gewoon een oranje balk met het label “database.”

rack-mini-profiler bevestigde het aantal queries: 47 in één request. Ergens itereerde de code en raakte daarbinnen de database. Maar waar? De action raakte veertig modellen aan via een diep genest aanroeppad. Ik had geen idee welke van die 47 queries het probleem was — of het probleem überhaupt de queries waren, of de Ruby-code ertussenin.

Dit is precies de situatie waarvoor rack-mini-profiler niet gebouwd is. Het is uitstekend voor de vraag welke laag van Rails traag is — ActiveRecord versus views versus middleware. Maar het vertelt je niet welke Ruby-code binnen die laag verantwoordelijk is. Daarvoor heb je een sampling-profiler nodig die de Ruby-aanroepstack zelf in de gaten houdt.

StackProf is dat gereedschap.

Wat Rails StackProf Is

StackProf is een sampling-profiler voor Ruby, geschreven door Koichi Sasada — ko1, de Ruby-kernontwerper die ook Fiber bouwde en een grote bijdrage leverde aan de YARV-VM. Het werkt door de Ruby-VM op regelmatige intervallen te onderbreken en de huidige aanroepstack op te nemen. Na een profileerrun heb je een statistisch beeld: frames die in 40% van de samples voorkomen, waren 40% van de tijd actief. De resolutie hangt af van de samplefrequentie, maar zelfs bij conservatieve intervallen krijg je genoeg signaal om knelpunten in seconden te identificeren.

De sampling-aanpak verschilt fundamenteel van instrumentatie. rack-mini-profiler wikkelt specifieke hooks — query-uitvoering, controller-dispatch, view-rendering — en meet de verstreken tijd rondom die hooks. StackProf ziet alles: jouw code, Rails-internals, gems, C-extensies waar ze aan de oppervlakte komen. Als 30% van je wall-time besteed wordt aan het deserialiseren van een modelattribuut dat je niet wist dat bij elke read werd geserialiseerd, laat StackProf dat zien. rack-mini-profiler schrijft die tijd toe aan “ActiveRecord” en gaat verder.

De overhead is laag. Bij het standaard interval van 1ms verwacht je 1–3% CPU-overhead. Bij 10ms minder dan 0,5%. Dit is veilig om in productie te draaien.

StackProf Installeren

Voeg het toe aan je Gemfile zonder een groepsbeperking, want je gaat het in productie gebruiken:

gem "stackprof"

Voer bundle install uit. Er is geen configuratiebestand nodig.

Profileren in de Rails-console

De snelste manier om een specifieke operatie te profileren is in de Rails-console, met echte data:

data = StackProf.run(mode: :wall, raw: true) do
  Report.generate_monthly(User.first, Date.today)
end

StackProf::Report.new(data).print_text(limit: 20)

raw: true slaat de volledige per-frame data op die nodig is voor flamegraph-uitvoer. Zonder dit kun je alleen de tekstsamenvatting lezen — geen flamegraph.

print_text geeft iets als dit:

 total    self
  47.2%  47.2%  ActiveRecord::ConnectionAdapters::PostgreSQL::OID::Integer#deserialize
  12.8%   0.0%  ActiveRecord::Result#initialize_copy
  11.4%   0.0%  Array#each
   8.9%   8.9%  PG::TypeMap#fit_to_copy_get
   4.1%   4.1%  Report#format_row

De kolom self toont frames waar het sample daadwerkelijk afvuurde — waar het proces op dat moment stond. De kolom total omvat tijd in alle frames die die methode aanriep. Een methode met hoge self-tijd is waar je CPU stopt. Een methode met hoge total maar lage self is een aggregator — die roept dure code stroomafwaarts aan.

Om de data op te slaan voor flamegraph-generatie:

data = StackProf.run(mode: :wall, raw: true) do
  Report.generate_monthly(User.first, Date.today)
end

File.binwrite(Rails.root.join("tmp/report_profile.dump"), Marshal.dump(data))

Vervolgens vanuit je terminal:

# Tekstsamenvatting
bundle exec stackprof tmp/report_profile.dump --text --limit 20

# Interactieve HTML-flamegraph
bundle exec stackprof tmp/report_profile.dump --d3-flamegraph > tmp/flamegraph.html
open tmp/flamegraph.html

Drie Profileeringsmodi

Het kiezen van de juiste modus verandert wat je ziet.

:wall-modus

Samplet op een realtimeklok, ongeacht wat de thread doet. Registreert tijd die geblokkeerd is op IO, wachten op Postgres, slapen in een mutex. Dit is de modus die ik als eerste gebruik bij een traag Rails-request, omdat de meeste Rails-latentie geen CPU is — het is wachten op de database, wachten op externe HTTP-aanroepen, wachten op Redis.

StackProf.run(mode: :wall, interval: 1000, raw: true) { ... }

interval is in microseconden. 1000 is 1ms, dus 1000 samples per seconde. Voor productie is 10000 (100 samples/seconde) conservatief en vrijwel gratis. Het reports-endpoint dat ik profileerde: :wall-modus toonde honderden samples in PG::Connection#exec_params en, cruciaal, precies welke Ruby-frames het in een lus aanriepen.

:cpu-modus

Vuurde samples alleen af wanneer het Ruby-proces gepland staat op CPU. IO-wachttijd, sleep en tijd geblokkeerd op externe aanroepen zijn onzichtbaar. Gebruik dit wanneer je een CPU-gebonden knelpunt vermoedt: stringverwerking, JSON-codering, complexe berekeningen, zware reguliere expressies. Als je request traag is maar :cpu bijna geen samples toont, is je knelpunt IO, niet berekening.

StackProf.run(mode: :cpu, interval: 1000, raw: true) { ... }

:object-modus

Telt objectallocaties in plaats van tijd. Samples worden afgevuurd bij elke N-de allocatie in plaats van op een timer. Gebruik dit wanneer GC-tuning laat zien dat je major GC-frequentie hoog is en je wilt weten welke code verantwoordelijk is.

StackProf.run(mode: :object, interval: 100, raw: true) { ... }

interval: 100 vuurde bij elke 100e allocatie. De flamegraph toont dan allocatieaantallen per frame in plaats van tijd. Hash#merge op 30% self-tijd betekent dat je code bij elke merge-aanroep een nieuw hash-object aanmaakt — vervang door merge! en kijk hoe de GC-druk daalt.

Een Flamegraph Lezen

Open de gegenereerde HTML of upload de dump naar Speedscope (browsergebaseerd, niets wordt geüpload). Drie regels:

Breedte staat gelijk aan tijd. Een breed frame bracht meer tijd door dan een smal frame. Negeer de diepte bij het scannen op problemen. Zoek naar brede frames bovenaan de zichtbare stack — dat zijn je knelpunten.

De stack groeit omhoog. Het onderste frame startte alles: Puma::Server#handle_request of de perform-methode van je job. Frames erboven zijn wat het aanriep. Het bovenste frame in een kolom is waar het sample afvuurde.

Positie is geen tijdsvolgorde. Flamegraphs sorteren frames standaard alfabetisch. Twee naast elkaar geplaatste frames hoeven niet opeenvolgend te zijn uitgevoerd.

Het nuttigste patroon om naar te zoeken: een breed frame bovenaan met één of twee aanroeper-frames direct daaronder die bijna even breed zijn. Dat betekent dat één codepad de tijd domineert, en door de keten omlaag te volgen zie je waar in je codebase het vandaan komt.

In het geval van het reports-endpoint toonde de flamegraph ActiveRecord::Associations::CollectionProxy#find op 41% totale wall-tijd, aangeroepen vanuit Reportable#format_row, aangeroepen vanuit Array#each, aangeroepen vanuit Report#build_rows. De N+1 stond daar in de flamegraph, duidelijk en gemeten. De fix — de association-load buiten de lus verplaatsen — bracht het endpoint van elf seconden terug naar 900ms.

Rack-middleware voor Productie

Het nuttigste wat je met StackProf kunt doen is het uitvoeren als productie-middleware die een klein percentage van het echte verkeer profileert en dump-bestanden naar schijf schrijft. Dit vangt trage paden op die je lokaal niet kunt reproduceren — zware data, ongebruikelijke parametercombinaties, effecten van gelijktijdige belasting.

# lib/stackprof_middleware.rb

class StackProfMiddleware
  SAMPLE_RATE = ENV.fetch("STACKPROF_SAMPLE_RATE", "0.005").to_f
  INTERVAL_US = ENV.fetch("STACKPROF_INTERVAL_US", "5000").to_i

  def initialize(app, mode: :wall)
    @app  = app
    @mode = mode
  end

  def call(env)
    return @app.call(env) unless rand < SAMPLE_RATE

    status = headers = body = nil
    data = StackProf.run(mode: @mode, interval: INTERVAL_US, raw: true) do
      status, headers, body = @app.call(env)
    end

    save(data, env)
    [status, headers, body]
  end

  private

  def save(data, env)
    return if data[:samples] < 3

    route = env
      .fetch("PATH_INFO", "unknown")
      .gsub(/[^a-z0-9\-_\/]/, "_")
      .delete_prefix("/")
      .tr("/", "_")[0, 40]

    ts   = Time.now.strftime("%Y%m%d_%H%M%S")
    name = "#{ts}-#{route}-#{SecureRandom.hex(4)}.dump"
    path = Rails.root.join("tmp", "stackprof", name)

    FileUtils.mkdir_p(path.dirname)
    File.binwrite(path, Marshal.dump(data))
  rescue => e
    Rails.logger.warn("StackProfMiddleware: #{e.message}")
  end
end

Registreer het in config/application.rb:

require_relative "../lib/stackprof_middleware"
config.middleware.use StackProfMiddleware

Met STACKPROF_SAMPLE_RATE=0.005 (de standaard) wordt één op de 200 requests geprofileerd. Op een app met 10 req/s is dat één profiel elke 20 seconden — beheersbaar. Op een app met 1000 req/s zijn dat vijf profielen per seconde — te veel dumps. Verlaag de rate naar 0.0005 voor apps met veel verkeer.

De omgevingsvariabele laat je sampling verhogen tijdens een incident zonder heruitrol: heroku config:set STACKPROF_SAMPLE_RATE=0.1 of het equivalent voor jouw platform.

Op een Kamal-implementatie (zie de Rails 8 Kamal-gids), haal dump-bestanden op uit de draaiende container:

kamal app exec --interactive -- ls tmp/stackprof
kamal app exec -- cat tmp/stackprof/20261020_143022-reports-a3f1.dump > local.dump
bundle exec stackprof local.dump --d3-flamegraph > flamegraph.html

Analyseren met Speedscope

De ingebouwde --d3-flamegraph HTML-viewer werkt, maar Speedscope heeft betere ergonomie voor langere sessies. Converteer een dump naar Speedscope-formaat:

bundle exec stackprof --speedscope tmp/local.dump > tmp/profile.json

Open speedscope.app en laad het JSON-bestand. Alles blijft lokaal — er wordt niets geüpload. Drie weergaven:

Left Heavy voegt identieke aanroepstacks samen en sorteert op totale tijd. Dit is de flamegraph-weergave. Gebruik deze als eerste.

Time Order behoudt de chronologische volgorde, van links naar rechts. Handig als een knelpunt episodisch verschijnt — een trage operatie die drie keer tijdens een request afvuurt, toont drie aparte vlamkolommen.

Sandwich geeft de tekstsamenvatting als sorteerbare tabel met self- en total-kolommen. Ik filter op mijn app-namespace (app/) om te focussen op code die ik beheer. Deze weergave alleen is vaak genoeg om het probleemframe te identificeren.

Achtergrond-jobs Profileren

Achtergrond-jobs zijn vaak de slechtst presterende code in een Rails-app. Ze draaien asynchroon, trage jobs falen stilzwijgend en prestatieproblemen worden pas zichtbaar wanneer wachtrijen vollopen. StackProf toevoegen aan een achtergrond-job is hetzelfde patroon:

class MonthlyReportJob < ApplicationJob
  PROFILE_RATE = ENV.fetch("JOB_STACKPROF_RATE", "0.02").to_f

  def perform(account_id, period)
    account = Account.find(account_id)

    if rand < PROFILE_RATE
      profiled_run(account, period)
    else
      generate(account, period)
    end
  end

  private

  def profiled_run(account, period)
    data = StackProf.run(mode: :wall, interval: 1000, raw: true) do
      generate(account, period)
    end

    name = "job-#{self.class.name.underscore}-#{SecureRandom.hex(6)}.dump"
    path = Rails.root.join("tmp", "stackprof", name)
    FileUtils.mkdir_p(path.dirname)
    File.binwrite(path, Marshal.dump(data))
  end

  def generate(account, period)
    Report.generate(account, period)
  end
end

Om een specifieke trage job te profileren, zet je tijdelijk JOB_STACKPROF_RATE=1.0 in je productieomgeving. Elke run van die job schrijft een dump. Haal een tiental dumps op, voer ze door de flamegraph-viewer en het knelpunt is duidelijk.

Objectallocatie Profileren

Wanneer je major GC-aantalletje hoog is maar je met tijdgebaseerde profilering de bron niet kunt vinden, schakel je over op :object-modus:

data = StackProf.run(mode: :object, interval: 10, raw: true) do
  Report.generate(account, period)
end
StackProf::Report.new(data).print_text(limit: 15)

interval: 10 vuurde bij elke 10e allocatie. Een typische uitvoer:

 total    self
  41.2%  41.2%  Hash#merge
  28.7%   0.0%  ActiveRecord::Core#init_with_attributes
  14.1%   0.0%  Array#map
   9.3%   9.3%  String#gsub

Hash#merge op 41% self-tijd: ergens in de hot loop maakt hash.merge(other_hash) bij elke aanroep een nieuw hash-object. Vervang door hash.merge!(other_hash) of bouw het hash-object één keer buiten de lus. ActiveRecord::Core#init_with_attributes op 28% totaal betekent dat de code veel ActiveRecord-objecten instantieert — overweeg select om het aantal attributen te beperken of pluck wanneer je alleen ruwe waarden nodig hebt en het modelobject niet gebruikt.

Veelvoorkomende Flamegraph-patronen

Na honderden Rails-flamegraphs te hebben gelezen, komen deze patronen regelmatig terug:

Breed read_attribute met veel identieke aanroepers — een geserialiseerd attribuut dat bij elke modelinstantiatie wordt gelezen. JSON- of Marshal-deserialisatie bij elke attribuuttoegang telt snel op. Sla de gedeserialiseerde waarde op in een instance-variabele als memoization.

Breed PG::Connection#exec_params aangeroepen vanuit Array#each — een klassieke N+1, zichtbaar in de flamegraph als een brede band met het lusframe direct eronder. Zie de N+1-post voor herstel, maar StackProf vertelt je de exacte Ruby-methode die het veroorzaakte.

Dunne frames voor String#gsub of Regexp#match verspreid door de flamegraph — regex-intensieve tekstverwerking verspreid over meerdere aanroeplocaties. Gecompileerde constanten (PATTERN = /foo/ op klasseniveau, niet binnenin methoden) helpen. Soms is het knelpunt niet de regex maar de stringallocatie eromheen.

Breed Marshal.load of JSON.parse — grote cachewaarden die bij elke cache-hit worden gedeserialiseerd. Overweeg kleinere objecten te cachen, gebruik oj in plaats van de stdlib JSON, of cache gerenderde HTML-fragmenten in plaats van ruwe datastructuren.

GC-frames verspreid door de flamegraph — allocatiedruk. Schakel over naar :object-modus om de bron te vinden.

FAQ

Hoe verhoudt Rails StackProf zich tot rack-mini-profiler?

Ze beantwoorden verschillende vragen. rack-mini-profiler beantwoordt “welke laag van Rails is traag?” — het wikkelt query-uitvoering, view-rendering en controller-dispatch en toont de uitsplitsing. StackProf beantwoordt “welke Ruby-code binnen die laag is verantwoordelijk?” Gebruik ze samen: rack-mini-profiler om de trage sectie te identificeren, StackProf om de specifieke methode te pinpointen. Voor elk Rails-request waarbij rack-mini-profiler naar “ActiveRecord” wijst maar niet kan vertellen welke code de queries aandrijft, schakel je over naar StackProf in :wall-modus.

Is StackProf veilig om in productie te draaien?

Ja, bij een verstandige samplefrequentie. Overhead bij het standaard interval van 1ms is 1–3%. Bij 10ms minder dan 0,5%. De hier beschreven middleware-aanpak profileert slechts een fractie van de requests, waardoor de totale overhead verwaarloosbaar blijft. Ik draai StackProf-middleware continu op meerdere productie-Rails-apps bij SAMPLE_RATE=0.005.

Wat is het verschil tussen :cpu en :wall mode in StackProf?

:cpu-modus vuurde alleen af wanneer de thread gepland staat op CPU. Tijd geblokkeerd op Postgres, Redis of externe HTTP is onzichtbaar. :wall-modus vuurde op een realtimeklok, ongeacht wat de thread doet — het registreert alle latentiebronnen. Voor een typisch Rails-webrequest waarbij de meeste tijd IO-wachttijd is, toont :wall het volledige beeld. Voor pure berekening — codering, hashing, datastructuren bouwen — is :cpu nauwkeuriger omdat het IO-ruis negeert.

Waarom ontbreken sommige Ruby-methoden in mijn flamegraph?

Twee redenen. Ten eerste: C-extensies — StackProf registreert Ruby-frames. Array#sort verschijnt als Array#sort, niet de C-vergelijkingsfunctie die erin uitvoert. Ten tweede: YJIT-inlining — Ruby 3.3+ en YJIT inlinen korte methoden, waardoor ze kunnen verschijnen samengevoegd met het aanroeper-frame of helemaal verdwijnen. Als een kritieke methode onzichtbaar is terwijl je YJIT draait, schakel je het uit voor de profileersessie met RUBY_YJIT_ENABLE=0 en vergelijk de flamegraphs.

Te veel tijd kwijt aan het najagen van trage Rails-endpoints zonder duidelijk beeld van waar het knelpunt zit? TTB Software profileert en optimaliseert productie-Rails-applicaties. We doen dit al negentien jaar.