Capturing ORM Plans with auto_explain #

You cannot run EXPLAIN ANALYZE on a query an ORM generated three layers below your code, with parameters that only appear under production load. auto_explain solves that: it hooks the executor and logs the actual plan of any statement exceeding a duration threshold, exactly as it ran, with the parameters it ran with.

This page covers the configuration that makes it useful for ORM traffic specifically. Reading the resulting plans is covered in ORM-generated EXPLAIN output.

What the Module Captures and What It Costs #

auto_explain is a contrib module that hooks the executor. When a statement’s duration exceeds auto_explain.log_min_duration, it writes that statement’s plan to the PostgreSQL log. The settings that matter for ORM work:

• log_min_duration — the threshold in milliseconds. -1 disables logging; 0 logs everything, which is a good way to fill a disk.
• log_analyze — include actual row counts and timings. Without it you get estimates only, which is far less useful.
• log_timing — per-node timing. This is the expensive one; on systems without a fast clock source it can add noticeable overhead to instrumented statements.
• log_buffers — include buffer counts, cheap and highly informative once log_analyze is on.
• log_nested_statements — capture statements inside functions and procedures, which is essential when an ORM routes work through stored procedures or triggers.
• log_format — text for humans, json for machine ingestion.

The important trade-off: overhead is proportional to instrumented statements, not to all statements. A threshold that only qualifies the slow tail keeps the cost where the information is.

Configuration for ORM Traffic #

Load the module for regular sessions without a restart:

ALTER SYSTEM SET session_preload_libraries = 'auto_explain';
ALTER SYSTEM SET auto_explain.log_min_duration = '200ms';
ALTER SYSTEM SET auto_explain.log_analyze = on;
ALTER SYSTEM SET auto_explain.log_buffers = on;
ALTER SYSTEM SET auto_explain.log_timing = off;      -- the expensive part
ALTER SYSTEM SET auto_explain.log_nested_statements = on;
ALTER SYSTEM SET auto_explain.log_format = 'json';
SELECT pg_reload_conf();

log_timing = off is the compromise worth understanding: you keep actual row counts, loop counts, and buffers — which is enough to diagnose almost every ORM plan problem — while dropping the per-node clock reads that cost the most.

A captured plan looks like an ordinary EXPLAIN ANALYZE, prefixed with the statement:

LOG:  duration: 812.402 ms  plan:
      Query Text: SELECT "orders"."id", "orders"."total_cents" FROM "orders"
                  WHERE "orders"."customer_id" = 4471 ORDER BY "orders"."created_at" DESC
      Limit  (actual rows=20 loops=1)
        ->  Sort  (actual rows=20 loops=1)
              Sort Key: created_at DESC
              Sort Method: top-N heapsort  Memory: 28kB
              ->  Seq Scan on orders  (actual rows=8412 loops=1)
                    Filter: (customer_id = 4471)
                    Buffers: shared read=91240

The quoted identifiers are the giveaway that an ORM produced it. The plan says the rest: no index on (customer_id, created_at), so a full scan feeds a top-N sort to return twenty rows.

Attributing a Plan to Application Code #

A logged plan without context is a puzzle. Two settings solve it.

First, make the ORM tag its SQL. Django exposes this through query annotation, SQLAlchemy through event hooks, ActiveRecord through query log tags — all of them prepend a comment that survives into the log:

/* view=orders.list request=8f21a4 */ SELECT "orders"."id" …

Second, put session identity in the log line itself:

ALTER SYSTEM SET log_line_prefix = '%m [%p] %u@%d app=%a ';
SELECT pg_reload_conf();

With application_name set by the connection string or pool configuration, every logged plan carries the service that issued it — which matters when several services share one database through a pooler, as described in PgBouncer transaction mode and prepared statements.

Step-by-Step Rollout #

1. Start on a replica or staging with log_min_duration = 0 briefly, to confirm the module is loaded and the format is what your log pipeline expects.

2. Choose a production threshold from your existing latency distribution — typically the 95th percentile of statement duration, so only the tail is instrumented.

3. Turn on nested statements if any ORM traffic goes through functions, triggers, or stored procedures; without it those plans are invisible.

4. Add the comment tagging in the application before you need it. Retrofitting attribution during an incident is unpleasant.

5. Correlate with aggregate statistics. auto_explain shows individual bad plans; pg_stat_statements shows which normalised statements consume the most total time:

   SELECT queryid, calls, total_exec_time, mean_exec_time, left(query, 70) AS query
     FROM pg_stat_statements ORDER BY total_exec_time DESC LIMIT 20;

   The combination catches both the slow statement and the fast statement executed 40,000 times — which is what an N+1 pattern looks like in aggregate.

6. Cap the volume. A threshold that suddenly qualifies thousands of statements per second will fill the disk; alert on log growth rate, not only on log content.

Before and After #

-- BEFORE: application metrics only
"the orders page is sometimes slow"    — no plan, no statement, no attribution

-- AFTER: auto_explain with tagging
LOG: duration: 812.402 ms  plan:
     Query Text: /* view=orders.list */ SELECT … ORDER BY created_at DESC LIMIT 20
     Limit → Sort (top-N heapsort) → Seq Scan on orders  Buffers: shared read=91240

The fix — an index on (customer_id, created_at DESC) — was obvious once the plan existed. Producing the plan was the whole problem.

Common Pitfalls #

Leaving log_timing on by default. It is the dominant cost of the module. Diagnostic signal: measurable slowdown on statements that cross the threshold. Fix: disable it and rely on rows, loops, and buffers.

Setting the threshold to zero in production. Every statement logs its plan, and the log becomes the bottleneck. Diagnostic signal: log volume growing by gigabytes per hour. Fix: threshold at the slow tail.

Missing nested statements. ORM work routed through functions or triggers never appears. Diagnostic signal: known-slow operations absent from the log. Fix: enable log_nested_statements.

Diagnosing an N+1 storm from auto_explain alone. Each individual query is fast and below the threshold. Diagnostic signal: no logged plans despite a slow page. Fix: use pg_stat_statements call counts alongside it.

Logging parameter values into a shared log. auto_explain.log_parameter_max_length controls how much of each bound parameter is recorded, and those values can be personal data. Diagnostic signal: customer identifiers or email addresses in a log shipped to a third-party aggregator. Fix: set the parameter length to zero unless the values are genuinely needed, and treat the plan log as production data.

Reading a single captured plan as the typical one. auto_explain shows the executions that crossed the threshold, which are by definition the unusual ones — a cold cache, an unlucky parameter, a lock wait. Diagnostic signal: a fix aimed at a plan that appears once in a day of logs. Fix: collect several captures of the same statement before concluding anything, and weight by the aggregate view.

Leaving it enabled and unmonitored. Configuration drifts, thresholds stop matching a changed workload, and the module quietly stops capturing anything useful — or captures far too much. Diagnostic signal: a log with either no plans for weeks or gigabytes per hour. Fix: review the threshold whenever latency targets change, and alert on both extremes.

Frequently Asked Questions #

Is auto_explain safe in production? With a sensible threshold and log_timing off, yes. The overhead is concentrated in instrumented statements, so a threshold that only qualifies the slow tail keeps the cost proportional to the value.

Why do my ORM queries not appear? Either they finish below log_min_duration, or they run inside functions while log_nested_statements is off. A threshold set high also hides the many individually fast queries that make up an N+1 storm.

How do I tell which code produced a plan? Have the ORM prepend a comment naming the view or request, and include %a in log_line_prefix with application_name set per service. Both travel into the log entry with the plan.

Related #

• ORM-Generated EXPLAIN Output — parent guide: reading what ORMs emit
• Interpreting SQLAlchemy-Generated Plans — sibling: one framework in depth
• ORM Translation Pitfalls — section overview: the plan cost of ORM abstractions
• Detecting N+1 in Django ORM — the pattern these logs help you find