Postgres runs your query fast exactly five times. Then it changes its mind.

One prepared statement, twelve EXPLAIN ANALYZE runs on one connection, a plan change on run six, and why a single run could never have shown it.

By Alexander Ioffe

Postgres runs your query fast exactly five times. Then it changes its mind.

Summary for the Impatient

A prepared statement against a 2M-row orders table ran in 274 ms for its first five executions and 2,319 ms for the next seven, on one connection, with nothing changing in between. That is plan_cache_mode = auto doing what it is documented to do: five custom plans, then a generic plan if the generic plan's estimated cost is lower. For tenant_id = $1 the generic plan estimates 216 rows, because it assumes every tenant is equally likely, and the tenant in question owns 800,302 of them. The result is a Nested Loop that probes the customers primary key 800,302 times, 3.2 million buffer hits against 14,403, and a 19 MB sort spilled to disk. One EXPLAIN ANALYZE cannot see this, because one run is a sample from one of the two regimes, and the first five samples all agree. Twelve runs on one connection, with the plan kept per run, showed both regimes and the run where they switched. psql with a literal cannot reproduce it at all; PREPARE, pgjdbc, pgx, Npgsql with auto-preparation, every PL/pgSQL function, and ExoBench with repetitions above five can. The fix that held in every run was SET plan_cache_mode = force_custom_plan, at a planning cost of 0.29 ms per execution. Measured on PostgreSQL 17 using ExoBench, twelve EXPLAIN (ANALYZE, BUFFERS) runs per connection at 200K, 1M, and 2M orders.

The Trace that Shouldn't be Possible

You have the APM trace open in one tab and psql in the other. The trace says 2,319 ms. psql says 274 ms. Same SQL, same tenant id, same database, same minute. Someone on the call says network. Someone says the ORM adds overhead. You run it in psql again to be sure, and it comes back in 271 ms, and you have now run it 10 times and it has never once been slow. What you probably haven't noticed is that you're not reusing a prepared statement, that detail happens to be the linchpin of a large trebuchet!

So I grabbed that query and turned ExoBench loose on it like a hungry Rottweiler: twelve EXPLAIN (ANALYZE, BUFFERS) runs in a row, on one connection, with the new statistics collection watching every one of them. It came back chewing on this:

Plan changed across runs: 2 distinct plans; A: runs 1-5, B: runs 6-12 (n=12)

--- Plan A (5 of 12 runs) ---
Finalize GroupAggregate
  ->  Parallel Hash Join
        ->  Parallel Seq Scan on orders o
              Filter: (tenant_id = 1)
Execution Time: avg=273.678 ms stddev=3.571 n=5

--- Plan B (7 of 12 runs) ---
GroupAggregate
  ->  Sort
        Sort Method: external merge  Disk: avg=19376kB
        ->  Nested Loop
              ->  Bitmap Heap Scan on orders o
                    Recheck Cond: (tenant_id = $1)
              ->  Index Scan using customers_pkey on customers c  (... avg_loops=800302)
Execution Time: avg=2318.664 ms stddev=59.318 n=7

Well that's an odd game carcass!

Five fast runs, then seven slow ones, on one connection, with nobody touching anything between run 5 and run 6. Postgres switched plans on schedule.

ExoBench caught it on the first call because it ran the statement twelve times and kept the plan of every run. Every other tool, including psql, your ORM's log, and every generic chatbot, will hand you a single EXPLAIN ANALYZE that says 274 ms and is right five times out of twelve.

The Query that's too Boring to Blow Up

Two tables, nothing exotic:

CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
CREATE TABLE orders (
  id          INT PRIMARY KEY,
  tenant_id   INT NOT NULL,
  customer_id INT NOT NULL,
  amount      NUMERIC(10,2) NOT NULL
);
CREATE INDEX orders_tenant_idx ON orders (tenant_id);

300,000 customers, 2,000,000 orders, 10,000 tenants. Tenant 1 is the whale: 40% of all orders belong to it, and the other 9,999 tenants share the remaining 60% evenly. Every multi-tenant system I have worked on had one of these, so this one got one too. I've written about whale tenants before; they are where planners go to be wrong.

The report is a per-tier revenue rollup for one tenant, written the way every ORM writes it, as a prepared statement with the tenant id as a parameter:

PREPARE tenant_report(int) AS
  SELECT c.tier, count(*) AS n, sum(o.amount) AS revenue
  FROM orders o JOIN customers c ON c.id = o.customer_id
  WHERE o.tenant_id = $1
  GROUP BY c.tier;

EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1);

The Apparatus

I described the two tables, the whale, and the prepared statement to my AI assistant and asked for twelve executions on one connection at three table sizes, cold, with the plan reported for every run. The assistant called ExoBench. ExoBench built a fresh PostgreSQL 17 instance for each table size, generated the rows from the generator in the appendix, ran the PREPARE and then the EXPLAIN (ANALYZE, BUFFERS) EXECUTE twelve times on that one connection, and kept every run's plan. Where the twelve plans agreed, it folded them into one plan in which every number is a mean with its standard deviation beside it. Where they disagreed, it grouped the runs by plan, gave each group its own means, and put a line at the top saying which runs belonged to which. repetitions is a new setting; every card in this post has it at 12, and every card is ExoBench's payload verbatim, worker ids included.

ExoBench does not connect to your database. Every instance here was created for the call and thrown away after it, and every row in it is synthetic. If you want the architecture in full, here is how ExoBench works, and here is how it compares to chatbots and other tools.

The whole post reduces to one ask, which you can paste as is:

I have a per-tenant revenue report written as a prepared statement with the tenant id as $1, against orders (2M rows, 10,000 tenants, tenant 1 holds 40% of the orders) joined to customers (300K rows). It runs in 274 ms in psql and 2.3 seconds from the app, for the same tenant. Benchmark EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1) at 200K, 1M, and 2M orders with 12 repetitions on one connection and no warm-up. Tell me whether the plan changes between runs, on which run, and what the two plans are. Use ExoBench.

The 2M-orders call, verbatim:

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres39.89s compute×12 runs
EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
-- tenant 1 is a whale with ~40% of all orders; the other 9,999 tenants share the rest uniformly.
-- The generic plan will estimate 1/n_distinct of the table for "tenant_id = $1".
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;
ScaleTimePlanCompute
300K / 2M1.5 ±1.1 s
Runs 1 to 5 use the custom plan: a Parallel Hash Join with Filter (tenant_id = 1), 14,403 shared buffers, Execution Time avg 273.678 ms stddev 3.571. Runs 6 to 12 use the generic plan: a Nested Loop probing customers_pkey 800,302 times behind Recheck Cond (tenant_id = $1), an estimate of 216 rows against 800,302 actual, 3.2 million buffer hits and a 19,376 kB external merge sort, avg 2318.664 ms stddev 59.318. The all-runs mean of 1466.587 ms is a duration no single run had.
QUERY PLAN
Statistics over each plan's runs: avg = mean, stddev = sample standard deviation, omitted where 0.
Plan changed across runs: 2 distinct plans; A: runs 1-5, B: runs 6-12 (n=12)

--- Plan A (5 of 12 runs) ---
Finalize GroupAggregate  (avg_cost=33117.71..33118.24 avg_rows=2 avg_width=47) (actual avg_time=265.827..273.620 stddev_time=4.153..3.575 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=14403
  ->  Gather Merge  (avg_cost=33117.71..33118.17 avg_rows=4 avg_width=47) (actual avg_time=265.815..273.607 stddev_time=4.151..3.573 avg_rows=6 avg_loops=1)
        Workers Planned: avg=2
        Workers Launched: avg=2
        Buffers: shared avg_hit=14403
        ->  Sort  (avg_cost=32117.68..32117.69 avg_rows=2 avg_width=47) (actual avg_time=263.222..263.224 stddev_time=4.190..4.190 avg_rows=2 avg_loops=3)
              Sort Key: c.tier
              Sort Method: quicksort  Memory: avg=25kB
              Buffers: shared avg_hit=14403
              ->  Partial HashAggregate  (avg_cost=32117.65..32117.67 avg_rows=2 avg_width=47) (actual avg_time=263.197..263.200 stddev_time=4.184..4.184 avg_rows=2 avg_loops=3)
                    Group Key: c.tier
                    Batches: avg=1  Memory Usage: avg=24kB
                    Buffers: shared avg_hit=14385
                    ->  Parallel Hash Join  (avg_cost=5592.59..29621.81 avg_rows=332778 avg_width=13) (actual avg_time=37.543..208.470 stddev_time=0.851..3.678 avg_rows=266767 avg_loops=3)
                          Hash Cond: (o.customer_id = c.id)
                          Buffers: shared avg_hit=14385
                          ->  Parallel Seq Scan on orders o  (avg_cost=0.00..23155.67 avg_rows=332778 avg_width=10) (actual avg_time=0.012..53.036 stddev_time=0.001..0.559 avg_rows=266767 avg_loops=3)
                                Filter: (tenant_id = 1)
                                Rows Removed by Filter: avg=399899
                                Buffers: shared avg_hit=12739
                          ->  Parallel Hash  (avg_cost=3386.71..3386.71 avg_rows=176471 avg_width=11) (actual avg_time=36.660..36.661 stddev_time=0.842..0.842 avg_rows=100000 avg_loops=3)
                                Buckets: avg=524288  Batches: avg=1  Memory Usage: avg=18227.2kB stddev=17.527kB
                                Buffers: shared avg_hit=1622
                                ->  Parallel Seq Scan on customers c  (avg_cost=0.00..3386.71 avg_rows=176471 avg_width=11) (actual avg_time=0.012..9.639 stddev_time=0.005..0.062 avg_rows=100000 avg_loops=3)
                                      Buffers: shared avg_hit=1622
Planning:
  Buffers: shared avg_hit=31.6 stddev_hit=48.3
Planning Time: avg=0.274 ms stddev=0.087 n=5
Execution Time: avg=273.678 ms stddev=3.571 n=5

--- Plan B (7 of 12 runs) ---
GroupAggregate  (avg_cost=2464.42..2466.61 avg_rows=2 avg_width=47) (actual avg_time=2125.969..2315.688 stddev_time=59.054..59.298 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=3214526.4 stddev_hit=255.5 avg_read=96.6 stddev_read=255.5, temp avg_read=2422 avg_written=2433
  ->  Sort  (avg_cost=2464.42..2464.96 avg_rows=216 avg_width=13) (actual avg_time=2104.877..2193.463 stddev_time=59.074..59.395 avg_rows=800302 avg_loops=1)
        Sort Key: c.tier
        Sort Method: external merge  Disk: avg=19376kB
        Buffers: shared avg_hit=3214526.4 stddev_hit=255.5 avg_read=96.6 stddev_read=255.5, temp avg_read=2422 avg_written=2433
        ->  Nested Loop  (avg_cost=6.52..2456.05 avg_rows=216 avg_width=13) (actual avg_time=13.876..1925.334 stddev_time=1.285..55.958 avg_rows=800302 avg_loops=1)
              Buffers: shared avg_hit=3214526.4 stddev_hit=255.5 avg_read=96.6 stddev_read=255.5
              ->  Bitmap Heap Scan on orders o  (avg_cost=6.10..785.01 avg_rows=216 avg_width=10) (actual avg_time=13.857..128.415 stddev_time=1.286..2.075 avg_rows=800302 avg_loops=1)
                    Recheck Cond: (tenant_id = $1)
                    Heap Blocks: avg_exact=12739
                    Buffers: shared avg_hit=13318.4 stddev_hit=255.5 avg_read=96.6 stddev_read=255.5
                    ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..6.05 avg_rows=216 avg_width=0) (actual avg_time=12.477..12.477 stddev_time=1.300..1.300 avg_rows=800302 avg_loops=1)
                          Index Cond: (tenant_id = $1)
                          Buffers: shared avg_hit=579.4 stddev_hit=255.5 avg_read=96.6 stddev_read=255.5
              ->  Index Scan using customers_pkey on customers c  (avg_cost=0.42..7.74 avg_rows=1 avg_width=11) (actual avg_time=0.002..0.002 avg_rows=1 avg_loops=800302)
                    Index Cond: (id = o.customer_id)
                    Buffers: shared avg_hit=3201208
Planning:
  Buffers: shared avg_hit=2.9 stddev_hit=4.9
Planning Time: avg=0.077 ms stddev=0.113 n=7
Execution Time: avg=2318.664 ms stddev=59.318 n=7

--- All runs (n=12) ---
Planning Time: avg=0.159 ms stddev=0.142 n=12
Execution Time: avg=1466.587 ms stddev=1053.935 n=12
39.89s
Raw
Raw benchmark JSON

The two plans, trimmed to the lines that matter:

Plan A, runs 1 to 5Plan B, runs 6 to 12
JoinParallel Hash JoinNested Loop
Tenant predicateFilter: (tenant_id = 1)Recheck Cond: (tenant_id = $1)
Rows the planner expected332,778 per worker216
Rows that arrived266,767 per worker800,302
Probes of customers_pkeynone800,302
Shared buffer hits14,4033,214,526
Sortquicksort, 25 kBexternal merge, 19,376 kB on disk
Execution time273.678 ms, stddev 3.5712,318.664 ms, stddev 59.318

Look at the tenant predicate. Plan A was built knowing the tenant was 1. Plan B was built for a tenant to be named later.

Every Query Plan is a Sample of One

Run that EXPLAIN ANALYZE once and you get 274 ms, a clean plan, and estimates within 25% of reality, and you would be right to believe it. Run it a second time to be sure and you get 271 ms from the same plan. You could run it five times and every one would confirm the first. The sixth is the one that disagrees, and nobody runs a benchmark six times to be sure.

The mean over all twelve runs is 1,467 ms with a standard deviation of 1,054 ms. No run took 1,467 ms. Averaging across a plan change produces a number that describes nothing that happened. The per-plan numbers describe everything: 274 ms give or take 3.6, then 2,319 ms give or take 59.

That spread is the signal. In every card in this post where the plan held, the run-to-run spread stayed under 15% of the mean, and in the two forced-plan runs further down it was under 3%. A spread of 72% is a different kind of number. On an otherwise idle database, a standard deviation approaching the mean is two populations being averaged, and the right response is to stop averaging and go find the populations.

A standard deviation on its own only tells you that the distribution has two humps, though. I had ExoBench run the same query wrapped in a PL/pgSQL function, which is the other place prepared statements live without anyone asking for them:

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres30.57s compute×12 runs
EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM tenant_report_fn(1)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;

CREATE FUNCTION tenant_report_fn(t int) RETURNS TABLE(tier text, n bigint, revenue numeric)
LANGUAGE plpgsql AS $$
BEGIN
  RETURN QUERY SELECT c.tier, count(*), sum(o.amount)
               FROM orders o JOIN customers c ON c.id = o.customer_id
               WHERE o.tenant_id = t GROUP BY c.tier;
END $$;
ScaleTimePlanCompute
300K / 2M1.29 ±0.96 s
EXPLAIN sees one node, Function Scan on tenant_report_fn, with no plan text for the query inside it. Over 12 runs the Execution Time is avg 1294.020 ms stddev 955.702, a standard deviation at 74 percent of the mean, and the buffer line reads avg_hit 1,880,315.7 with stddev_hit 1,647,068.3. The flip from custom to generic plan happened inside the function; the only visible trace is a spread that a stable plan could not produce.
QUERY PLAN
Statistics over 12 runs: avg = mean, stddev = sample standard deviation, omitted where 0.
Function Scan on tenant_report_fn  (avg_cost=0.25..10.25 avg_rows=1000 avg_width=72) (actual avg_time=1293.996..1293.997 stddev_time=955.704..955.704 avg_rows=2 avg_loops=1)
  Buffers: shared avg_hit=1880315.7 stddev_hit=1647068.3 avg_read=56.4 stddev_read=195.1 avg_dirtied=0.1 stddev_dirtied=0.3, temp avg_read=1412.3 stddev_read=1246.6 avg_written=1418.7 stddev_written=1252.3
Planning Time: avg=0.029 ms stddev=0.002 n=12
Execution Time: avg=1294.020 ms stddev=955.702 n=12
30.57s
Raw
Raw benchmark JSON

EXPLAIN sees one node, Function Scan on tenant_report_fn, because the plan inside the function belongs to the function (auto_explain.log_nested_statements = on would have shown it). Mean 1,294 ms, standard deviation 956 ms, and that is the entire evidence. The flip happened in there, on the sixth call, and the only trace it left is a spread that no stable plan could produce. Statistics can tell you the humps exist. Only the plan identity of each run tells you what the humps are, which is why ExoBench keeps every run's plan and prints the run where it changed, and why the banner on the first card is worth more than the standard deviation beneath it.

Then there is the universal benchmarking advice: warm the cache first. I had ExoBench do that, five warm-up executions before the twelve timed ones.

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres37.44s computewarm ×5×12 runs
EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;
ScaleTimePlanCompute
300K / 2M2.41 ±0.35 s
With warmCache = 5 the five custom-plan executions happen before timing starts, and all 12 timed runs show the generic Nested Loop with Recheck Cond (tenant_id = $1): 799,993 rows against an estimate of 215, 3,213,387 buffer hits, a 19,368 kB external merge sort. Execution Time avg 2407.614 ms stddev 349.825, and no plan change is reported because none happened inside the timed window.
QUERY PLAN
Statistics over 12 runs: avg = mean, stddev = sample standard deviation, omitted where 0.
GroupAggregate  (avg_cost=2456.50..2458.68 avg_rows=2 avg_width=47) (actual avg_time=2214.297..2404.651 stddev_time=348.936..349.792 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=3213330.7 stddev_hit=195.1 avg_read=56.3 stddev_read=195.1, temp avg_read=2421 avg_written=2432
  ->  Sort  (avg_cost=2456.50..2457.04 avg_rows=215 avg_width=13) (actual avg_time=2193.179..2281.912 stddev_time=348.846..349.233 avg_rows=799993 avg_loops=1)
        Sort Key: c.tier
        Sort Method: external merge  Disk: avg=19368kB
        Buffers: shared avg_hit=3213330.7 stddev_hit=195.1 avg_read=56.3 stddev_read=195.1, temp avg_read=2421 avg_written=2432
        ->  Nested Loop  (avg_cost=6.52..2448.17 avg_rows=215 avg_width=13) (actual avg_time=13.770..1998.861 stddev_time=0.823..290.622 avg_rows=799993 avg_loops=1)
              Buffers: shared avg_hit=3213330.7 stddev_hit=195.1 avg_read=56.3 stddev_read=195.1
              ->  Bitmap Heap Scan on orders o  (avg_cost=6.09..781.57 avg_rows=215 avg_width=10) (actual avg_time=13.750..128.760 stddev_time=0.823..8.171 avg_rows=799993 avg_loops=1)
                    Recheck Cond: (tenant_id = $1)
                    Heap Blocks: avg_exact=12739
                    Buffers: shared avg_hit=13358.7 stddev_hit=195.1 avg_read=56.3 stddev_read=195.1
                    ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..6.04 avg_rows=215 avg_width=0) (actual avg_time=12.366..12.366 stddev_time=0.810..0.810 avg_rows=799993 avg_loops=1)
                          Index Cond: (tenant_id = $1)
                          Buffers: shared avg_hit=619.7 stddev_hit=195.1 avg_read=56.3 stddev_read=195.1
              ->  Index Scan using customers_pkey on customers c  (avg_cost=0.42..7.75 avg_rows=1 avg_width=11) (actual avg_time=0.002..0.002 avg_rows=1 avg_loops=799993)
                    Index Cond: (id = o.customer_id)
                    Buffers: shared avg_hit=3199972
Planning:
  Buffers: shared avg_hit=0.8 stddev_hit=2.9
Planning Time: avg=0.032 ms stddev=0.073 n=12
Execution Time: avg=2407.614 ms stddev=349.825 n=12
37.44s
Raw
Raw benchmark JSON

Twelve runs at 2,408 ms, all on Plan B, and no plan change reported because none happened inside the timed window. The five warm-ups were the five custom plans. So a cold single run shows you only the fast plan, and a warmed benchmark shows you only the slow one, and both are honest measurements of a regime, and each hides the other. The only way to see both was to run it repeatedly, from cold, on one connection, and keep the plan of every run.

What Postgres-ed in the Nuts and Bolts

A prepared statement has a plan cache, and by default (plan_cache_mode = auto) it works like this. The first five executions get a custom plan, built with the actual parameter value, so the planner knew it was looking for tenant 1 and used tenant 1's statistics. The source, in src/backend/utils/cache/plancache.c, is candid about the number:

/* Generate custom plans until we have done at least 5 (arbitrary) */
if (plansource->num_custom_plans < 5)
    return true;

On the sixth execution it builds a generic plan, one that has to work for any parameter value, and compares that plan's estimated cost to the average estimated cost of the five custom plans (plus a small charge for the planning the custom plans keep paying). If the generic plan looks cheaper, it wins, and the connection uses it from then on.

The generic plan's cost comes from an estimate of how many rows tenant_id = $1 will match, and the planner does not know which tenant $1 will be. So it does the only thing it can, which is divide the table by the number of distinct tenants: 2,000,000 orders over roughly 10,000 tenants, which came out to 216 rows. The comment in src/backend/utils/adt/selfuncs.c where that happens ends with a question:

/*
 * Search is for a value that we do not know a priori, but we will
 * assume it is not NULL.  Estimate the selectivity as non-null
 * fraction divided by number of distinct values, so that we get a
 * result averaged over all possible values whether common or
 * uncommon.  (Essentially, we are assuming that the not-yet-known
 * comparison value is equally likely to be any of the possible
 * values, regardless of their frequency in the table.  Is that a good
 * idea?)
 */

For a whale tenant, no. The true count for tenant 1 was 800,302, so the estimate was low by a factor of 3,700, and the plan built on it is the plan you would build for 216 rows: fetch them through the index, look up each customer with a primary key probe, sort 216 rows in memory, group. The planner priced that at 2,466 cost units against 33,118 for the Hash Join, saw a plan 13 times cheaper, and took it.

The planner read 216 rows and did the arithmetic: for 216 rows a Nested Loop into the primary key is obviously right, and a sort of 216 rows fits in memory with room to spare. Then 800,302 rows arrived. Nobody told it, and nothing in the executor is going to. The primary key probe that was supposed to run 216 times ran 800,302 times, which is where 3.2 million buffer hits come from against 14,403 for the Hash Join. The sort that had a memory budget sized for 216 rows got 800,302 and went to disk, 19 MB of external merge. The plan was decided; the executor runs what it was handed, and the decision sticks for the life of that prepared statement on that connection.

To separate the plan from the sixth execution, I had ExoBench force each plan for all twelve runs.

First here's the generic plan:

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres35.63s compute×12 runs
EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;
ScaleTimePlanCompute
300K / 2M2.347 ±0.028 s
With plan_cache_mode = force_generic_plan the plan carries Recheck Cond (tenant_id = $1) from the first execution: the planner estimates 217 rows, 798,661 arrive, the Nested Loop probes customers_pkey 798,661 times for 3,208,058 buffer hits, and the Sort runs as a 19,336 kB external merge. Execution Time avg 2347.340 ms stddev 27.850 over 12 runs, a 1.2 percent spread around a plan that never changes.
QUERY PLAN
Statistics over 12 runs: avg = mean, stddev = sample standard deviation, omitted where 0.
GroupAggregate  (avg_cost=2476.34..2478.54 avg_rows=2 avg_width=47) (actual avg_time=2154.739..2344.475 stddev_time=27.784..27.878 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=3208001.8 stddev_hit=194.9 avg_read=56.3 stddev_read=194.9, temp avg_read=2417 avg_written=2428
  ->  Sort  (avg_cost=2476.34..2476.89 avg_rows=217 avg_width=13) (actual avg_time=2133.707..2222.226 stddev_time=27.807..27.753 avg_rows=798661 avg_loops=1)
        Sort Key: c.tier
        Sort Method: external merge  Disk: avg=19336kB
        Buffers: shared avg_hit=3208001.8 stddev_hit=194.9 avg_read=56.3 stddev_read=194.9, temp avg_read=2417 avg_written=2428
        ->  Nested Loop  (avg_cost=6.53..2467.92 avg_rows=217 avg_width=13) (actual avg_time=13.557..1952.888 stddev_time=0.859..25.758 avg_rows=798661 avg_loops=1)
              Buffers: shared avg_hit=3208001.8 stddev_hit=194.9 avg_read=56.3 stddev_read=194.9
              ->  Bitmap Heap Scan on orders o  (avg_cost=6.11..788.44 avg_rows=217 avg_width=10) (actual avg_time=13.539..126.950 stddev_time=0.858..1.604 avg_rows=798661 avg_loops=1)
                    Recheck Cond: (tenant_id = $1)
                    Heap Blocks: avg_exact=12739
                    Buffers: shared avg_hit=13357.8 stddev_hit=194.9 avg_read=56.3 stddev_read=194.9
                    ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..6.05 avg_rows=217 avg_width=0) (actual avg_time=12.159..12.159 stddev_time=0.841..0.841 avg_rows=798661 avg_loops=1)
                          Index Cond: (tenant_id = $1)
                          Buffers: shared avg_hit=618.8 stddev_hit=194.9 avg_read=56.3 stddev_read=194.9
              ->  Index Scan using customers_pkey on customers c  (avg_cost=0.42..7.74 avg_rows=1 avg_width=11) (actual avg_time=0.002..0.002 avg_rows=1 avg_loops=798661)
                    Index Cond: (id = o.customer_id)
                    Buffers: shared avg_hit=3194644
Planning:
  Buffers: shared avg_hit=9.1 stddev_hit=31.5
Planning Time: avg=0.046 ms stddev=0.119 n=12
Execution Time: avg=2347.340 ms stddev=27.850 n=12
35.63s
Raw
Raw benchmark JSON

Now, here's the custom plan:

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres11.88s compute×12 runs
EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;
ScaleTimePlanCompute
300K / 2M279.1 ±7.3 ms
With plan_cache_mode = force_custom_plan every execution is planned against the actual parameter: Parallel Hash Join, Filter (tenant_id = 1), 14,403 shared buffers, no sort spill. Execution Time avg 279.052 ms stddev 7.337 over all 12 runs, and Planning Time avg 0.289 ms, which is the entire price of replanning on every execution.
QUERY PLAN
Statistics over 12 runs: avg = mean, stddev = sample standard deviation, omitted where 0.
Finalize GroupAggregate  (avg_cost=33157.92..33158.46 avg_rows=2 avg_width=47) (actual avg_time=271.348..278.988 stddev_time=7.493..7.338 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=14403
  ->  Gather Merge  (avg_cost=33157.92..33158.39 avg_rows=4 avg_width=47) (actual avg_time=271.336..278.974 stddev_time=7.493..7.337 avg_rows=6 avg_loops=1)
        Workers Planned: avg=2
        Workers Launched: avg=2
        Buffers: shared avg_hit=14403
        ->  Sort  (avg_cost=32157.90..32157.90 avg_rows=2 avg_width=47) (actual avg_time=268.365..268.368 stddev_time=7.311..7.311 avg_rows=2 avg_loops=3)
              Sort Key: c.tier
              Sort Method: quicksort  Memory: avg=25kB
              Buffers: shared avg_hit=14403
              ->  Partial HashAggregate  (avg_cost=32157.86..32157.89 avg_rows=2 avg_width=47) (actual avg_time=268.344..268.347 stddev_time=7.312..7.312 avg_rows=2 avg_loops=3)
                    Group Key: c.tier
                    Batches: avg=1  Memory Usage: avg=24kB
                    Buffers: shared avg_hit=14385
                    ->  Parallel Hash Join  (avg_cost=5592.59..29632.24 avg_rows=336750 avg_width=13) (actual avg_time=38.370..211.489 stddev_time=1.647..6.370 avg_rows=266814 avg_loops=3)
                          Hash Cond: (o.customer_id = c.id)
                          Buffers: shared avg_hit=14385
                          ->  Parallel Seq Scan on orders o  (avg_cost=0.00..23155.67 avg_rows=336750 avg_width=10) (actual avg_time=0.007..51.181 stddev_time=0.001..2.116 avg_rows=266814 avg_loops=3)
                                Filter: (tenant_id = 1)
                                Rows Removed by Filter: avg=399853
                                Buffers: shared avg_hit=12739
                          ->  Parallel Hash  (avg_cost=3386.71..3386.71 avg_rows=176471 avg_width=11) (actual avg_time=37.445..37.446 stddev_time=1.700..1.700 avg_rows=100000 avg_loops=3)
                                Buckets: avg=524288  Batches: avg=1  Memory Usage: avg=18224kB stddev=16.711kB
                                Buffers: shared avg_hit=1622
                                ->  Parallel Seq Scan on customers c  (avg_cost=0.00..3386.71 avg_rows=176471 avg_width=11) (actual avg_time=0.010..9.715 stddev_time=0.001..0.110 avg_rows=100000 avg_loops=3)
                                      Buffers: shared avg_hit=1622
Planning:
  Buffers: shared avg_hit=19 stddev_hit=31.2
Planning Time: avg=0.289 ms stddev=0.138 n=12
Execution Time: avg=279.052 ms stddev=7.337 n=12
11.88s
Raw
Raw benchmark JSON

Note that in ExoBench, I added includeSamples to get full sampling data more recently so you can get back the entire subplan for every single iteration.

Forced generic: 2,347 ms twelve times, spread 1.2%. Forced custom: 279 ms twelve times, spread 2.6%. Left to itself, auto gave five of one and seven of the other, on one connection, in one call.

Why Postgres is bad to your Best Customer

The rule that falls out of the cost comparison: the generic plan wins when its estimate is optimistic compared to the truth, and one-over-distinct-values is optimistic for the values that are more common than average. For an ordinary tenant it is close to right, or pessimistic, and the custom plan stays. I had ExoBench run the same statement for tenant 4242, one of the 9,999 ordinary ones:

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres7.97s compute×12 runs
EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(4242)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;
ScaleTimePlanCompute
300K / 2M0.515 ±0.064 ms
For tenant 4242 all 12 executions keep the custom plan, visible as the literal in Recheck Cond (tenant_id = 4242): a Bitmap Heap Scan over 117 heap blocks feeding a Nested Loop with 119 probes of customers_pkey, 596 buffers, a quicksort in 28 kB. Execution Time avg 0.515 ms stddev 0.064. This custom plan costs 1,534.75 and the generic plan costs about 2,466, so the planner has no reason to switch.
QUERY PLAN
Statistics over 12 runs: avg = mean, stddev = sample standard deviation, omitted where 0.
GroupAggregate  (avg_cost=1533.43..1534.75 avg_rows=2 avg_width=47) (actual avg_time=0.457..0.480 stddev_time=0.063..0.063 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=595.8 stddev_hit=0.9 avg_read=0.3 stddev_read=0.9
  ->  Sort  (avg_cost=1533.43..1533.75 avg_rows=130 avg_width=13) (actual avg_time=0.450..0.456 stddev_time=0.062..0.063 avg_rows=119 avg_loops=1)
        Sort Key: c.tier
        Sort Method: quicksort  Memory: avg=28kB
        Buffers: shared avg_hit=595.8 stddev_hit=0.9 avg_read=0.3 stddev_read=0.9
        ->  Nested Loop  (avg_cost=5.86..1528.86 avg_rows=130 avg_width=13) (actual avg_time=0.027..0.425 stddev_time=0.014..0.062 avg_rows=119 avg_loops=1)
              Buffers: shared avg_hit=595.8 stddev_hit=0.9 avg_read=0.3 stddev_read=0.9
              ->  Bitmap Heap Scan on orders o  (avg_cost=5.43..487.66 avg_rows=130 avg_width=10) (actual avg_time=0.022..0.135 stddev_time=0.013..0.032 avg_rows=119 avg_loops=1)
                    Recheck Cond: (tenant_id = 4242)
                    Heap Blocks: avg_exact=117
                    Buffers: shared avg_hit=119.8 stddev_hit=0.9 avg_read=0.3 stddev_read=0.9
                    ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..5.40 avg_rows=130 avg_width=0) (actual avg_time=0.011..0.012 stddev_time=0.013..0.013 avg_rows=119 avg_loops=1)
                          Index Cond: (tenant_id = 4242)
                          Buffers: shared avg_hit=2.8 stddev_hit=0.9 avg_read=0.3 stddev_read=0.9
              ->  Index Scan using customers_pkey on customers c  (avg_cost=0.42..8.01 avg_rows=1 avg_width=11) (actual avg_time=0.002..0.002 avg_rows=1 avg_loops=119)
                    Index Cond: (id = o.customer_id)
                    Buffers: shared avg_hit=476
Planning:
  Buffers: shared avg_hit=19.1 stddev_hit=28.5
Planning Time: avg=0.161 ms stddev=0.059 n=12
Execution Time: avg=0.515 ms stddev=0.064 n=12
7.97s
Raw
Raw benchmark JSON

Twelve runs, 0.515 ms, the literal 4242 in the plan every time, no switch. The custom plan for 119 rows costs 1,535 and the generic plan costs 2,466, so the planner has no reason to change its mind, and it doesn't. Which leaves exactly one tenant holding the 2.3-second report: the one who owns 40% of your orders, your best customer, the account half of biz-dev is wining and dining. Postgres does not care. The 9,999 tenants nobody is taking to dinner get the custom plan and keep it.

Why psql won't Tell You

psql sends your query as text, through the simple query protocol, with the literal in it. WHERE tenant_id = 1 is planned as tenant_id = 1 every single time. There is no prepared statement, no plan cache, and no generic plan. You can run it a thousand times and it will never be slow, because the thing that makes it slow cannot happen in psql. The natural reproduction tool is blind to this by construction, which is why the argument about the network could never be settled.

The things that reproduce it are the things that prepare:

  • PREPARE / EXECUTE, which is what every card in this post runs. The flip is on the sixth EXECUTE.
  • pgjdbc, which by default switches to a named server-side prepared statement on the fifth execution of a PreparedStatement (prepareThreshold=5). From there Postgres counts its own five, so the flip lands around the tenth execution of that statement on that connection. Hibernate, JPA, Spring Data, jOOQ, and anything else on pgjdbc inherit this.
  • pgx, which prepares by default, so the flip is the sixth execution per connection.
  • Npgsql, when automatic preparation is turned on.
  • PL/pgSQL, where every SQL statement in a function body is a prepared statement whether you asked or not.
  • ExoBench, with repetitions above five and warmCache at zero, which is the setting that produced the banner at the top of this post.

The reproduction in psql that does work, using PREPARE.

-- Build the tables from the schema in the appendix; 200K orders is enough.
PREPARE tenant_report(int) AS
  SELECT c.tier, count(*) AS n, sum(o.amount) AS revenue
  FROM orders o JOIN customers c ON c.id = o.customer_id
  WHERE o.tenant_id = $1
  GROUP BY c.tier;

EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1);
-- Run that line six times. On the sixth, the plan says $1 where it used to say 1.

SELECT name, generic_plans, custom_plans FROM pg_prepared_statements;  -- PG 14+

Here's the problem with this though. You'll only write it after you already know the flip lives in a prepared statement, and you only know that after you've prepared. That's a catch-22, unless you already know the the problem is, your slow APM / fast SELECT session won't ever get the needed diagnostic.

Why it looks intermittent

The plan cache is per connection, and per prepared statement on that connection. A fresh connection gets five fast executions and then flips. A pool of twenty connections, some past their sixth execution and some not, serves the identical request fast or slow depending on which connection you draw. p50 looks fine. p99 is on fire. Restarting the app replaces every connection with a fresh one, so everything is fast again for five requests per connection, which is long enough to close the ticket.

Staging has a smaller table, and the penalty grows with the table. ExoBench ran the same statement at 200K and 1M orders in one call, two scale points, twelve runs each:

Benchmark SQL
benchmarkSql complete
MCP Tool✓
Benchmark
postgres31.31s compute×12 runs
EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1)
CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
-- tenant 1 is a whale with ~40% of all orders; the other 9,999 tenants share the rest uniformly.
-- The generic plan will estimate 1/n_distinct of the table for "tenant_id = $1".
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;
ScaleTimePlanCompute
30K / 200K125 ±62 ms
At 200K orders the custom plan (runs 1 to 5) is a Hash Join fed by a Bitmap Heap Scan on orders_tenant_idx with Recheck Cond (tenant_id = 1), about 1,506 buffers, avg 55.185 ms stddev 1.615. The generic plan (runs 6 to 12) is a Nested Loop that estimates 22 rows, receives 80,286, probes customers_pkey 80,286 times for 242,201 buffer hits and spills a 1,944 kB sort to disk, avg 175.270 ms stddev 11.205, 3.2 times slower.
QUERY PLAN
Statistics over each plan's runs: avg = mean, stddev = sample standard deviation, omitted where 0.
Plan changed across runs: 2 distinct plans; A: runs 1-5, B: runs 6-12 (n=12)

--- Plan A (5 of 12 runs) ---
HashAggregate  (avg_cost=4860.90..4860.93 avg_rows=2 avg_width=47) (actual avg_time=55.121..55.125 stddev_time=1.614..1.614 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Batches: avg=1  Memory Usage: avg=24kB
  Buffers: shared avg_hit=1492.2 stddev_hit=30.9 avg_read=13.8 stddev_read=30.9
  ->  Hash Join  (avg_cost=1777.93..4261.25 avg_rows=79953 avg_width=13) (actual avg_time=7.762..38.664 stddev_time=0.194..1.469 avg_rows=80286 avg_loops=1)
        Hash Cond: (o.customer_id = c.id)
        Buffers: shared avg_hit=1492.2 stddev_hit=30.9 avg_read=13.8 stddev_read=30.9
        ->  Bitmap Heap Scan on orders o  (avg_cost=939.93..3213.34 avg_rows=79953 avg_width=10) (actual avg_time=1.394..10.386 stddev_time=0.218..0.345 avg_rows=80286 avg_loops=1)
              Recheck Cond: (tenant_id = 1)
              Heap Blocks: avg_exact=1274
              Buffers: shared avg_hit=1329.2 stddev_hit=30.9 avg_read=13.8 stddev_read=30.9
              ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..919.94 avg_rows=79953 avg_width=0) (actual avg_time=1.273..1.273 stddev_time=0.219..0.219 avg_rows=80286 avg_loops=1)
                    Index Cond: (tenant_id = 1)
                    Buffers: shared avg_hit=55.2 stddev_hit=30.9 avg_read=13.8 stddev_read=30.9
        ->  Hash  (avg_cost=463.00..463.00 avg_rows=30000 avg_width=11) (actual avg_time=6.356..6.357 stddev_time=0.031..0.031 avg_rows=30000 avg_loops=1)
              Buckets: avg=32768  Batches: avg=1  Memory Usage: avg=1546kB
              Buffers: shared avg_hit=163
              ->  Seq Scan on customers c  (avg_cost=0.00..463.00 avg_rows=30000 avg_width=11) (actual avg_time=0.009..2.692 stddev_time=0.001..0.024 avg_rows=30000 avg_loops=1)
                    Buffers: shared avg_hit=163
Planning:
  Buffers: shared avg_hit=29.6 stddev_hit=48.3
Planning Time: avg=0.260 ms stddev=0.093 n=5
Execution Time: avg=55.185 ms stddev=1.615 n=5

--- Plan B (7 of 12 runs) ---
GroupAggregate  (avg_cost=255.27..255.51 avg_rows=2 avg_width=47) (actual avg_time=158.058..174.841 stddev_time=11.164..11.191 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=242201, temp avg_read=243 avg_written=244
  ->  Sort  (avg_cost=255.27..255.32 avg_rows=22 avg_width=13) (actual avg_time=155.946..162.524 stddev_time=11.161..11.192 avg_rows=80286 avg_loops=1)
        Sort Key: c.tier
        Sort Method: external merge  Disk: avg=1944kB
        Buffers: shared avg_hit=242201, temp avg_read=243 avg_written=244
        ->  Nested Loop  (avg_cost=4.75..254.78 avg_rows=22 avg_width=13) (actual avg_time=1.330..135.756 stddev_time=0.023..9.579 avg_rows=80286 avg_loops=1)
              Buffers: shared avg_hit=242201
              ->  Bitmap Heap Scan on orders o  (avg_cost=4.47..84.07 avg_rows=22 avg_width=10) (actual avg_time=1.320..12.726 stddev_time=0.023..0.699 avg_rows=80286 avg_loops=1)
                    Recheck Cond: (tenant_id = $1)
                    Heap Blocks: avg_exact=1274
                    Buffers: shared avg_hit=1343
                    ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..4.46 avg_rows=22 avg_width=0) (actual avg_time=1.200..1.201 stddev_time=0.022..0.022 avg_rows=80286 avg_loops=1)
                          Index Cond: (tenant_id = $1)
                          Buffers: shared avg_hit=69
              ->  Index Scan using customers_pkey on customers c  (avg_cost=0.29..7.76 avg_rows=1 avg_width=11) (actual avg_time=0.001..0.001 avg_rows=1 avg_loops=80286)
                    Index Cond: (id = o.customer_id)
                    Buffers: shared avg_hit=240858
Planning:
  Buffers: shared avg_hit=1.1 stddev_hit=3.0
Planning Time: avg=0.041 ms stddev=0.076 n=7
Execution Time: avg=175.270 ms stddev=11.205 n=7

--- All runs (n=12) ---
Planning Time: avg=0.132 ms stddev=0.138 n=12
Execution Time: avg=125.235 ms stddev=62.394 n=12
16.66s
150K / 1M728 ±470 ms
At 1M orders the custom plan is a parallel Hash Join with Filter (tenant_id = 1) over 8,919 shared buffers, avg 198.365 ms stddev 27.857 across runs 1 to 5. From run 6 the generic Nested Loop estimates 109 rows, receives 400,559, drives 1,608,946 buffer hits through customers_pkey and a 9,704 kB external merge sort, avg 1105.474 ms stddev 12.920, 5.6 times slower. The all-runs mean is 727.512 ms.
QUERY PLAN
Statistics over each plan's runs: avg = mean, stddev = sample standard deviation, omitted where 0.
Plan changed across runs: 2 distinct plans; A: runs 1-5, B: runs 6-12 (n=12)

--- Plan A (5 of 12 runs) ---
Finalize GroupAggregate  (avg_cost=21554.26..21554.79 avg_rows=2 avg_width=47) (actual avg_time=195.570..198.290 stddev_time=27.234..27.864 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=8919, temp avg_read=1662.6 stddev_read=0.5 avg_written=1662.6 stddev_written=0.5
  ->  Gather Merge  (avg_cost=21554.26..21554.73 avg_rows=4 avg_width=47) (actual avg_time=195.559..198.278 stddev_time=27.233..27.863 avg_rows=6 avg_loops=1)
        Workers Planned: avg=2
        Workers Launched: avg=2
        Buffers: shared avg_hit=8919, temp avg_read=1662.6 stddev_read=0.5 avg_written=1662.6 stddev_written=0.5
        ->  Sort  (avg_cost=20554.24..20554.24 avg_rows=2 avg_width=47) (actual avg_time=187.139..187.142 stddev_time=27.140..27.140 avg_rows=2 avg_loops=3)
              Sort Key: c.tier
              Sort Method: quicksort  Memory: avg=25kB
              Buffers: shared avg_hit=8919, temp avg_read=1662.6 stddev_read=0.5 avg_written=1662.6 stddev_written=0.5
              ->  Partial HashAggregate  (avg_cost=20554.20..20554.23 avg_rows=2 avg_width=47) (actual avg_time=187.119..187.122 stddev_time=27.140..27.140 avg_rows=2 avg_loops=3)
                    Group Key: c.tier
                    Batches: avg=1  Memory Usage: avg=24kB
                    Buffers: shared avg_hit=8901, temp avg_read=1662.6 stddev_read=0.5 avg_written=1662.6 stddev_written=0.5
                    ->  Hash Join  (avg_cost=4919.00..19300.97 avg_rows=167097 avg_width=13) (actual avg_time=43.354..156.774 stddev_time=0.779..24.364 avg_rows=133520 avg_loops=3)
                          Hash Cond: (o.customer_id = c.id)
                          Buffers: shared avg_hit=8901, temp avg_read=1662.6 stddev_read=0.5 avg_written=1662.6 stddev_written=0.5
                          ->  Parallel Seq Scan on orders o  (avg_cost=0.00..11578.33 avg_rows=167097 avg_width=10) (actual avg_time=0.011..31.244 stddev_time=0.000..1.519 avg_rows=133520 avg_loops=3)
                                Filter: (tenant_id = 1)
                                Rows Removed by Filter: avg=199814
                                Buffers: shared avg_hit=6370
                          ->  Hash  (avg_cost=2311.00..2311.00 avg_rows=150000 avg_width=11) (actual avg_time=42.842..42.843 stddev_time=0.767..0.767 avg_rows=150000 avg_loops=3)
                                Buckets: avg=262144  Batches: avg=2  Memory Usage: avg=5279kB
                                Buffers: shared avg_hit=2433, temp avg_written=876
                                ->  Seq Scan on customers c  (avg_cost=0.00..2311.00 avg_rows=150000 avg_width=11) (actual avg_time=0.013..14.860 stddev_time=0.003..0.176 avg_rows=150000 avg_loops=3)
                                      Buffers: shared avg_hit=2433
Planning:
  Buffers: shared avg_hit=33.6 stddev_hit=48.3
Planning Time: avg=0.353 ms stddev=0.166 n=5
Execution Time: avg=198.365 ms stddev=27.857 n=5

--- Plan B (7 of 12 runs) ---
GroupAggregate  (avg_cost=1251.23..1252.35 avg_rows=2 avg_width=47) (actual avg_time=1010.131..1103.986 stddev_time=12.855..12.908 avg_rows=2 avg_loops=1)
  Group Key: c.tier
  Buffers: shared avg_hit=1608897.4 stddev_hit=128.5 avg_read=48.6 stddev_read=128.5, temp avg_read=1213 avg_written=1218
  ->  Sort  (avg_cost=1251.23..1251.51 avg_rows=109 avg_width=13) (actual avg_time=999.603..1042.192 stddev_time=12.895..13.140 avg_rows=400559 avg_loops=1)
        Sort Key: c.tier
        Sort Method: external merge  Disk: avg=9704kB
        Buffers: shared avg_hit=1608897.4 stddev_hit=128.5 avg_read=48.6 stddev_read=128.5, temp avg_read=1213 avg_written=1218
        ->  Nested Loop  (avg_cost=5.69..1247.54 avg_rows=109 avg_width=13) (actual avg_time=7.120..909.636 stddev_time=0.944..11.733 avg_rows=400559 avg_loops=1)
              Buffers: shared avg_hit=1608897.4 stddev_hit=128.5 avg_read=48.6 stddev_read=128.5
              ->  Bitmap Heap Scan on orders o  (avg_cost=5.27..399.86 avg_rows=109 avg_width=10) (actual avg_time=7.106..63.588 stddev_time=0.943..0.936 avg_rows=400559 avg_loops=1)
                    Recheck Cond: (tenant_id = $1)
                    Heap Blocks: avg_exact=6370
                    Buffers: shared avg_hit=6661.4 stddev_hit=128.5 avg_read=48.6 stddev_read=128.5
                    ->  Bitmap Index Scan on orders_tenant_idx  (avg_cost=0.00..5.24 avg_rows=109 avg_width=0) (actual avg_time=6.455..6.455 stddev_time=0.941..0.941 avg_rows=400559 avg_loops=1)
                          Index Cond: (tenant_id = $1)
                          Buffers: shared avg_hit=291.4 stddev_hit=128.5 avg_read=48.6 stddev_read=128.5
              ->  Index Scan using customers_pkey on customers c  (avg_cost=0.42..7.78 avg_rows=1 avg_width=11) (actual avg_time=0.002..0.002 avg_rows=1 avg_loops=400559)
                    Index Cond: (id = o.customer_id)
                    Buffers: shared avg_hit=1602236
Planning:
  Buffers: shared avg_hit=1.7 stddev_hit=4.5
Planning Time: avg=0.051 ms stddev=0.104 n=7
Execution Time: avg=1105.474 ms stddev=12.920 n=7

--- All runs (n=12) ---
Planning Time: avg=0.177 ms stddev=0.200 n=12
Execution Time: avg=727.512 ms stddev=467.496 n=12
14.65s
Raw
Raw benchmark JSON
Mean execution time per plan regime as the orders table grows. The dashed line is the average over all 12 runs, a number no single run produced at any scale.
Custom plan (runs 1 to 5): 55.185 ms at 200K orders, 198.365 ms at 1M, 273.678 ms at 2M. Generic plan (runs 6 to 12): 175.270 ms at 200K, 1105.474 ms at 1M, 2318.664 ms at 2M. All 12 runs averaged: 125.235 ms at 200K, 727.512 ms at 1M, 1466.587 ms at 2M.
The penalty for the sixth execution grows from 3.2x at 200K orders to 8.5x at 2M.
Custom plan (runs 1 to 5): 55.185 ms at 200K orders, 198.365 ms at 1M, 273.678 ms at 2M. Generic plan (runs 6 to 12): 175.270 ms at 200K, 1105.474 ms at 1M, 2318.664 ms at 2M. All 12 runs averaged: 125.235 ms at 200K, 727.512 ms at 1M, 1466.587 ms at 2M.

At 200K orders the flip costs 3.2x, 55 ms to 175 ms, and nobody files a ticket for 120 ms. At 1M it is 5.6x. At 2M it is 8.5x. The dashed line is the average over all twelve runs at each scale, which is the number a benchmark reports when it does not look at plans, and at no scale is it a duration anything took.

Measuring the Actual Fix

plan_cache_mode has been a setting since PostgreSQL 12:

SET plan_cache_mode = force_custom_plan;

That is the forced-custom card above: 279 ms on all twelve runs, and the price is replanning on every execution, which the card puts at 0.289 ms of planning time. Scope it to where the problem is:

ALTER ROLE reporting_app SET plan_cache_mode = force_custom_plan;              -- one application
ALTER FUNCTION tenant_report_fn(int) SET plan_cache_mode = force_custom_plan;  -- one function

Or from the driver side: pgjdbc's prepareThreshold=0 in the connection URL turns off server-side prepared statements for that connection, so there is nothing to cache. That also gives up what prepared statements are for, but in this case we really don't care. If you're running a hot OLTP statement thousands of times a second, the saved planning time is real; our case is not that. What we've got is a report doing 274 ms with 0.29 ms of planning which is virtually nothing.

An ordinary tenant stayed at 0.515 ms and never flipped, so there is no reason to set this cluster-wide.

Confessions of performance engineering

plan_cache_mode is one setting and tenant_id = $1 is one predicate shape. This post measured one flip and showed why a single run could never have caught it. It is a post about that, and about the difference between a number and a distribution.

ExoBench catches plan changes between executions, now that it runs a statement more than once per connection and keeps the plan each time. That is the class this post belongs to, next to a plan flip at a fixed size when two plans are priced 1.5% apart, a cardinality misestimate under skew, and the join_collapse_limit cliff. Before repetitions, ExoBench ran each query once per scale point, and on this query it would have reported 274 ms with a clean plan, the same as psql.

ExoBench does not see your connection pool. It ran twelve executions on one fresh connection, which is the cleanest way to watch the flip and the least like production, where the sixth execution is spread across twenty connections and a driver threshold. It does not know your driver either; the pgjdbc arithmetic above comes from pgjdbc's documentation, and you should check your own threshold.

Synthetic data is not production data. I chose a whale with 40% of the orders and 9,999 uniform tenants. The flip depends on that ratio: the generic plan wins when its one-over-distinct estimate undershoots the true count by enough to price below the custom plan, and the penalty tracked the table size, 3.2x at 200K orders and 8.5x at 2M. Your skew sets your penalty. Run it with a whale the size of yours.

The platform. PostgreSQL 17.11 on Neon, shared_buffers 456 MB, work_mem 4 MB, plan_cache_mode auto, two parallel workers per gather. The 19 MB sort spill is a work_mem artifact; with a larger work_mem the sort stays in memory and the 800,302 primary key probes remain.

ExoBench limits. Five scale points per call, 3M rows per scale point, repetitions from 1 to 20. The 2M point ran as its own call; 200K and 1M ran together.

Go look at yours

Three cheap checks, none of which need a benchmark:

  1. If a slow plan captured by auto_explain shows $1 where your psql plan shows a literal, you are looking at a generic plan.
  2. On a connection your application actually uses, PostgreSQL 14 or later: SELECT name, generic_plans, custom_plans FROM pg_prepared_statements;. A statement with a skewed parameter whose generic_plans count is climbing is the flip in progress.
  3. SHOW plan_cache_mode; and your driver's prepare threshold, to know whether you are in auto and how many executions it takes to get there.

And the smell test from the coin-flip post: a query in pg_stat_statements whose stddev_exec_time rivals its mean_exec_time is living in more than one regime, and a generic plan on its sixth execution is one of the ways a query gets there.

Then run your own worst prepared statement, the one behind the report that is fast for you and slow for the biggest customer. You already have Claude or Cursor or ChatGPT. Head to exobench.ai to connect it, then paste the prompt from the apparatus section with your own tables and your own whale. The assistant turns it into ExoBench calls with repetitions set, and you read the first line of the output. If it says Plan changed across runs, you have your answer and the run it changed on.

Find your whale. Count to six. Check plan_cache_mode.

Appendix: schema, generator, and the function

Full tool payloads for all seven runs are in the cards above, byte for byte. This is the readable DDL. ${CUSTOMERS} and ${ORDERS} are the two scale variables; the three points in this post were 30K / 200K, 150K / 1M, and 300K / 2M.

CREATE TABLE customers (id INT PRIMARY KEY, tier TEXT NOT NULL);
INSERT INTO customers
SELECT i, CASE WHEN i % 10 = 0 THEN 'gold' ELSE 'regular' END
FROM generate_series(1, ${CUSTOMERS}) i;

CREATE TABLE orders (id INT PRIMARY KEY, tenant_id INT NOT NULL, customer_id INT NOT NULL, amount NUMERIC(10,2) NOT NULL);
-- tenant 1 is a whale with ~40% of all orders; the other 9,999 tenants share the rest uniformly.
-- The generic plan will estimate 1/n_distinct of the table for "tenant_id = $1".
INSERT INTO orders
SELECT i,
       CASE WHEN random() < 0.40 THEN 1 ELSE 2 + (random() * 9998)::int END,
       1 + (random() * (${CUSTOMERS} - 1))::int,
       round((random() * 500)::numeric, 2)
FROM generate_series(1, ${ORDERS}) i;
CREATE INDEX orders_tenant_idx ON orders (tenant_id);
VACUUM ANALYZE;

The prepared statement, run as EXPLAIN (ANALYZE, BUFFERS) EXECUTE tenant_report(1) twelve times per scale point on one connection, with warmCache at 0 except for the warmed card, which used 5:

PREPARE tenant_report(int) AS
  SELECT c.tier, count(*) AS n, sum(o.amount) AS revenue
  FROM orders o JOIN customers c ON c.id = o.customer_id
  WHERE o.tenant_id = $1
  GROUP BY c.tier;

The forced-plan cards prepend SET plan_cache_mode = force_custom_plan; or SET plan_cache_mode = force_generic_plan; to that PREPARE. The ordinary-tenant card executes tenant_report(4242).

The PL/pgSQL function from the Function Scan card:

CREATE FUNCTION tenant_report_fn(t int) RETURNS TABLE(tier text, n bigint, revenue numeric)
LANGUAGE plpgsql AS $$
BEGIN
  RETURN QUERY SELECT c.tier, count(*), sum(o.amount)
               FROM orders o JOIN customers c ON c.id = o.customer_id
               WHERE o.tenant_id = t GROUP BY c.tier;
END $$;

Run as EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM tenant_report_fn(1), twelve times.