Rails pg_stat_statements: Vind Trage Queries in Productie Voordat Je Gebruikers Het Doen

De pagina was traag. Niet catastrofaal traag — gewoon traag genoeg dat de product manager dingen bleef zeggen als “voelt sloom” en de on-call engineer bleef antwoorden met “bij mij werkt het prima”. APM zei dat de mediane request 180 milliseconden was. De p95 was 2,4 seconden. Niemand was het eens over welke query schuldig was, en de discussie ging al drie weken in cirkels.

Ik stelde één vraag. “Staat pg_stat_statements aan?” Niemand wist het. We zetten het aan, wachtten vier uur, en draaiden één query tegen pg_stat_statements. Het antwoord was binnen zestig seconden overduidelijk: één enkele ActiveRecord scope die op het dashboard gebruikt werd, was verantwoordelijk voor eenenveertig procent van alle database-tijd over de hele vloot. Niet de traagste query in absolute zin. Niet de meest frequente. Maar wel de query waarvan het product van frequentie en kosten per call het cluster aan het slopen was.

Na negentien jaar Rails is pg_stat_statements de meest onderbenutte Postgres-extensie in productie Rails-deployments. Het is ook het goedkoopste, snelste pad van “de app voelt traag” naar “hier is de exacte query om te fixen”. Als je Rails op Postgres draait en je hebt het niet aangezet, vlieg je blind.

Wat Rails pg_stat_statements Eigenlijk Doet

pg_stat_statements is een Postgres-extensie die elke SQL-statement die tegen de database wordt uitgevoerd een fingerprint geeft, en vervolgens uitvoeringsstatistieken per fingerprint aggregeert. Een fingerprint is de querytekst met literale waarden vervangen door placeholders, dus deze twee queries vouwen samen tot dezelfde rij:

SELECT * FROM users WHERE email = 'alice@example.com';
SELECT * FROM users WHERE email = 'bob@example.com';

Beide worden:

SELECT * FROM users WHERE email = $1;

Voor elke fingerprint houdt de extensie totaal aantal executies, totale tijd, gemiddelde tijd, min, max, standaarddeviatie, geretourneerde rijen, shared buffer hits, blocks gelezen van schijf en diverse andere tellers bij. De output is één view — pg_stat_statements — die je een platte ranglijst geeft van waar je database zijn tijd écht besteedt.

Dit is belangrijk omdat slow query logs liegen. Slow query logs surfacen individuele queries die een drempel overschreden. Ze missen de query die tienduizend keer per uur op 50ms loopt. Die query is onzichtbaar voor log_min_duration_statement = 500 maar vertegenwoordigt 500 seconden database-tijd per uur. pg_stat_statements vangt hem bij de eerste sortering.

Rails pg_stat_statements Aanzetten in Productie

De extensie wordt meegeleverd met Postgres maar wordt niet standaard geladen. Je hebt drie dingen nodig: een shared_preload_libraries entry, een configuratieblok en een CREATE EXTENSION call binnen de database.

In postgresql.conf (of de parameter group van je managed provider):

shared_preload_libraries = 'pg_stat_statements'
pg_stat_statements.max = 10000
pg_stat_statements.track = top
pg_stat_statements.track_utility = off
pg_stat_statements.save = on

Herstart Postgres. Dit is niet optioneel — shared_preload_libraries wordt alleen actief bij startup. Op RDS of Cloud SQL pas je de parameter group aan en reboot je de instance.

Zet vervolgens de extensie aan in de daadwerkelijke database. Voeg een Rails-migratie toe:

class EnablePgStatStatements < ActiveRecord::Migration[8.0]
  def up
    execute "CREATE EXTENSION IF NOT EXISTS pg_stat_statements"
  end

  def down
    execute "DROP EXTENSION IF EXISTS pg_stat_statements"
  end
end

Draai de migratie. Controleer dat het gelukt is:

SELECT extname, extversion
FROM pg_extension
WHERE extname = 'pg_stat_statements';

De eerste query zal waarschijnlijk vrijwel direct één rij teruggeven. Vanaf nu wordt elke statement die Rails stuurt geaggregeerd in een fingerprint-teller.

De overhead is verwaarloosbaar. Op elke Postgres-deployment waar ik het gemeten heb, kost pg_stat_statements minder dan één procent CPU en een paar megabyte shared memory. De kosten van uit laten staan zijn enorm; de kosten van aan laten staan zijn onzichtbaar.

De Ene Query Die Het Meest Toe Doet

Nieuwkomers bij pg_stat_statements openen de view, zien achtentwintig kolommen en bevriezen. Negeer de meeste ervan. De ene query die je negentig procent van de tijd draait is deze:

SELECT
  query,
  calls,
  ROUND(total_exec_time::numeric / 1000, 2) AS total_seconds,
  ROUND(mean_exec_time::numeric, 2)         AS mean_ms,
  ROUND((100 * total_exec_time
         / SUM(total_exec_time) OVER ())::numeric, 2) AS pct_total
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 20;

Dit rangschikt elke query-fingerprint op totale wandkloktijd doorgebracht in de database. De top van deze lijst is waar je database-tijd naartoe gaat. Punt.

Niet gemiddelde tijd. Gemiddelde tijd vertelt je welke individuele query traag was. Totale tijd vertelt je welke fingerprint je het meeste geld kost en de meeste gebruikers vertraagt. Een query die één keer draait en tien seconden duurt is minder belangrijk dan een query die een miljoen keer op 10ms draait.

Draai die query tegen productie nadat de extensie minstens een paar uur heeft verzameld. De eerste paar rijen zijn bijna altijd verrassend — niet omdat iemand incompetent is, maar omdat productieverkeer een andere vorm heeft dan ontwikkelaarsintuïtie. De top drie queries op de meeste Rails-apps die ik audit zijn een combinatie van: een sessie-lookup, een permissie-check op elke request en een “recente activiteit”-feed op het dashboard.

De Output Lezen Als Een Engineer, Niet Als Een Toerist

mean_exec_time is gemiddelde uitvoeringstijd per call. Snelle queries met lage gemiddelde tijd kunnen total_exec_time nog steeds domineren als ze constant draaien. Trage queries met hoge gemiddelde tijd zijn misschien niet relevant als ze eens per dag draaien.

calls is het aantal calls sinds de laatste reset van de extensie. Let hier op. Een query die tien miljoen keer per uur draait maar 0,5ms duurt is een kandidaat voor caching, niet voor query-optimalisatie — je kunt hem niet veel sneller maken, je kunt hem alleen minder vaak laten draaien. Een query die tien keer op vijf seconden per stuk draait is een kandidaat voor een index of een herschrijving.

stddev_exec_time vertelt je hoe consistent de query is. Een hoge standaarddeviatie betekent dat de query meestal snel is maar af en toe catastrofaal — meestal een teken van een query plan dat tussen een index scan en een sequential scan flipt op basis van parameterwaarden. Dit zijn de queries die door code review heen komen en vervolgens iemand om 3 uur ‘s nachts pagen.

shared_blks_hit versus shared_blks_read vertelt je over cachegedrag. Hits zijn pages gevonden in de shared buffer van Postgres. Reads zijn pages opgehaald van schijf (of de OS page cache, wat nog steeds sneller is dan schijf). Een query met hoge shared_blks_read ten opzichte van shared_blks_hit doet I/O. Of hij raakt te veel data, of je shared_buffers is te klein.

rows gedeeld door calls vertelt je hoeveel data elke call gemiddeld retourneert. Een query die drie rijen per call retourneert maar een miljoen blocks leest, leest en filtert het grootste deel van een tabel. Dat is je uitnodiging om een index toe te voegen.

Rails-Specifieke Patronen Die Bovenaan Verschijnen

Drie patronen domineren de top van pg_stat_statements op vrijwel elke Rails-app die ik ooit geaudit heb. Elk heeft een bekende fix.

De N+1 die je gemist hebt. Een query als SELECT * FROM comments WHERE post_id = $1 met dertig miljoen calls en nul gemiddelde tijd per call is een N+1. De fix is een includes of preload ergens — de truc is uitzoeken waar. Voeg een APM-trace toe of gebruik strict loading in development om de call sites te vangen. pg_stat_statements vertelt je dát de N+1 bestaat; tracing vertelt je waar hij woont.

De “active scope” die de wereld scant. Een query als SELECT * FROM orders WHERE status IN ($1,$2,$3) AND created_at > $4 met hoge gemiddelde tijd en hoge shared_blks_read is meestal een ontbrekende composite index. Kijk naar de WHERE-clause, bepaal welke kolommen het meest selectief zijn en voeg de index toe. De helft van de tijd heeft de query ook een ORDER BY die de index kan bevredigen, waardoor een sortering een no-op wordt.

De sessie-lookup op elke request. Devise-gebruikers zien een users lookup op id bovenaan de lijst met een call-count gelijk aan het totale aantal requests. Dit is geen bug — het is elke authenticated request — maar het kan database-tijd domineren als de lookup meer werk doet dan nodig. Controleer dat de users-tabel wordt opgezocht op primary key (dat zou moeten) en dat je geen zware associatie eager loaded in je current-user lookup.

Het patroon: scan de top twintig rijen één keer per week. De fixes zijn meestal klein. De winsten stapelen op.

Queries Normaliseren Over Omgevingen Heen

pg_stat_statements normaliseert literale waarden, maar normaliseert geen structureel verschillende queries. Twee queries die alleen verschillen in hun kolomlijst zijn verschillende fingerprints. Dit bijt Rails-apps omdat select(:id, :name) van ActiveRecord versus select(:id, :name, :email) twee fingerprints produceert, elk met een fractie van de calls.

Dit kun je niet vanuit Postgres oplossen. Vanuit Rails kun je het wel oplossen. Inspecteer de top van de lijst op fingerprints die duidelijk dezelfde logische query zijn met verschillende kolomlijsten. Bepaal een canonieke projectie en gebruik die overal. Meestal is de fix het verwijderen van een verdwaalde .pluck(:id, :name) of .select(...) die in een serializer is geslopen.

Hetzelfde gebeurt met IN-lijsten van wisselende lengte. WHERE id IN ($1) en WHERE id IN ($1, $2) zijn verschillende fingerprints in oudere Postgres-versies. Postgres 14 en later normaliseren deze tot één fingerprint met een generieke array-placeholder, wat één van de betere redenen is om op een actuele Postgres-versie te zitten.

De Statistieken Resetten Voor Een Gericht Onderzoek

pg_stat_statements accumuleert tellers sinds de laatste reset. Voor een gericht onderzoek — “wat is traag tijdens de ochtendpiek?” — reset de tellers aan het begin van het venster en lees ze aan het einde:

SELECT pg_stat_statements_reset();

Reset, wacht een uur, draai de top-20 query. Je krijgt een schoon beeld van wat de database-tijd in dat specifieke venster domineerde, niet vervuild door batch jobs van gisteren en migraties van vorige week.

Doe dit als je iets specifieks najaagt. Doe het niet routinematig — de langlopende aggregatie is nuttiger voor capacity planning en het opmerken van langzame drift in de tijd.

pg_stat_statements In Een Wekelijkse Cadans Inbouwen

De fout die teams maken is pg_stat_statements als een incident-tool behandelen. Ze zetten het aan tijdens een brand, vinden één slechte query en vergeten het dan weer. Het juiste patroon is een wekelijkse cadans.

Mijn Rails-klanten draaien een klein ActiveRecord-rapport één keer per week tegen pg_stat_statements, dumpen de top twintig in een Slack-channel en bespreken het in de reguliere engineering sync van het team. Totale kosten: tien minuten menselijke aandacht per week. Totale baten: elke regressie en elke trage drift wordt binnen een week gevangen, en het team leert geleidelijk wat hun database eigenlijk doet.

Een minimale versie van het rapport:

class DatabaseHotspots
  def self.top(limit: 20)
    sql = <<~SQL
      SELECT
        query,
        calls,
        ROUND(total_exec_time::numeric / 1000, 2) AS total_seconds,
        ROUND(mean_exec_time::numeric, 2)         AS mean_ms,
        ROUND((100 * total_exec_time
               / SUM(total_exec_time) OVER ())::numeric, 2) AS pct_total
      FROM pg_stat_statements
      ORDER BY total_exec_time DESC
      LIMIT $1
    SQL

    ActiveRecord::Base.connection.exec_query(sql, "DatabaseHotspots", [limit])
  end
end

Wire dat in een recurring Solid Queue job die elke maandagochtend draait, post het resultaat naar Slack, en je hebt database-observability geïnstitutionaliseerd met ongeveer dertig regels code.

Wanneer pg_stat_statements Niet Genoeg Is

pg_stat_statements vertelt je welke queries pijn doen. Het vertelt je niet waarom ze pijn doen. Daarvoor heb je EXPLAIN ANALYZE op het daadwerkelijke query plan nodig, en mogelijk auto_explain om plans van trage queries in productie vast te leggen zonder handmatige interventie.

Het vertelt je ook niets over lock waits. Een query met hoge mean_exec_time en lage shared_blks_read wacht vaak op een lock in plaats van werk te doen. Voor lockonderzoek wil je pg_locks en pg_stat_activity, niet pg_stat_statements.

En het vangt geen queries die falen. Een query die een timeout krijgt en wordt teruggedraaid draagt zijn uitvoeringstijd bij aan de aggregatie, maar als je een query hebt die elke keer dat hij draait wordt afgekapt door een statement timeout, zie je hem in pg_stat_statements met hoge gemiddelde tijd en lage call-count. De informatie is er als je ernaar zoekt.

Het punt is niet dat pg_stat_statements de enige tool is. Het punt is dat het de goedkoopste, hoogste-signaal tool is die je aan een Rails Postgres-deployment kunt toevoegen, en bijna niemand heeft hem aanstaan.

Veelgestelde Vragen

Hoeveel overhead voegt Rails pg_stat_statements toe in productie?

Op elke Postgres-deployment waar ik het gemeten heb, voegt pg_stat_statements minder dan één procent CPU-overhead en een paar megabyte shared memory toe. De default pg_stat_statements.max = 5000 is prima voor de meeste Rails-apps; ik schroef het op naar 10000 op apps met veel verschillende query-fingerprints. De kosten zijn verwaarloosbaar vergeleken met de zichtbaarheid die je krijgt.

Moet ik sorteren op total_exec_time of mean_exec_time bij het vinden van Rails trage queries?

Sorteer eerst op total_exec_time. Dat rangschikt queries op de totale wandkloktijd die ze je database kosten, wat is wat je applicatie daadwerkelijk vertraagt en je cloud-rekening oppompt. mean_exec_time is nuttig als secundaire view — als je eenmaal weet welke query totale tijd domineert, vertelt gemiddelde tijd je of je de query zelf of de aanroepfrequentie moet optimaliseren. Een query bovenaan total_exec_time met lage gemiddelde tijd is een kandidaat voor caching; één met hoge gemiddelde tijd is een kandidaat voor herschrijven of een index.

Werkt Rails pg_stat_statements met PgBouncer transaction pooling?

Ja. pg_stat_statements draait binnen Postgres zelf, dus het ziet elke statement ongeacht hoe de connectie gepooled was. De view aggregeert per query-fingerprint over alle backends. Als je PgBouncer transaction pooling draait, schakel pg_stat_statements in aan de Postgres-kant, niet op PgBouncer, en je krijgt een compleet beeld van elke query die je Rails-app door de pooler stuurt.

Hoe reset ik pg_stat_statements-tellers veilig in productie?

Roep SELECT pg_stat_statements_reset(); aan vanuit een sessie met voldoende rechten. Dit reset de aggregatietellers maar stopt de verzameling niet — nieuwe statements blijven direct accumuleren. Resetten is veilig tijdens kantooruren; de enige “kosten” zijn het verlies van je historische aggregatie. Voor een gericht onderzoek reset je vóór het venster van interesse, wacht je, en query je dan. Voor routinematige monitoring laat je de aggregatie weken aan een stuk lopen en reset je alleen wanneer je een schone lei wilt na een grote deployment.

Hulp nodig bij het inrichten van database-observability in je Rails-app, of bij het opjagen van de trage queries die pg_stat_statements net heeft blootgelegd? TTB Software is gespecialiseerd in Rails-performance en Postgres production tuning. We doen dit al negentien jaar.