The Slow Query That Ran in Four Milliseconds Under EXPLAIN

In production the query took nine hundred milliseconds. Under EXPLAIN it ran in four. The difference was the plan: production ran a cached generic plan…

Share
The Slow Query That Ran in Four Milliseconds Under EXPLAIN. Abstract bug hunt illustration in orange and dark grey on debugly.dev

The report query was slow in the application, reliably, for one customer and not the others. Pasted into a database session with the same parameter, it was instant. EXPLAIN agreed it was instant. Nothing about the application's connection looked different, and yet the two executions of the same SQL produced plans a hundred times apart in cost.

The gap is the prepared statement plan cache, and specifically the choice between a custom plan and a generic plan. It is one of the quietest performance defects in Postgres, because every tool you reach for shows you the fast plan while production runs the slow one.

This was Postgres 16.3 with a driver using server side prepared statements, and the slow customer was the one whose parameter value made the generic plan wrong.

The symptom, precisely

The application executed the statement through the extended protocol with a parameter. After a handful of executions, Postgres evaluated whether to keep planning per execution or switch to a generic plan, and for this statement it switched. The generic plan cannot use the parameter's value, so it chooses a plan that is reasonable on average. For most customers the average plan was fine. For the large customer, whose rows dominate the table, the average plan is the wrong plan, and every execution paid for it.

When I ran EXPLAIN with a literal, I got a custom plan built for that literal, which is the fast plan. So the tool showed the truth and the production connection ran a different truth, and the two never met.

The hypotheses that died

The data changed between my test and production

First I assumed my test data differed. I ran the query against the production data, with a literal, and it was fast. The data was the same.

It died because the data was never the variable. The plan was.

The connection settings differ

Next I compared connection settings, search path, work mem, between my session and the app. They matched.

It died because the settings were equal and the plans still differed, which pointed at something about how the statement itself was executed, not the session.

Statistics are stale

Then I suspected stale statistics producing a bad plan. I analysed the table and the production query was still slow, with the same generic shape.

It died because fresh statistics change custom plans, but the production execution was not building a custom plan at all.

The breakthrough

The difference between my session and the application was that mine sent literals and the application sent a prepared statement with parameters. Postgres's rule is that a prepared statement is planned custom for the first few executions, then compared against a generic plan, and if the generic plan's estimated cost is not much worse, it is adopted and reused for all subsequent executions, without the parameter values.

So the application, after warm up, ran the generic plan forever, and the generic plan for a heavily skewed parameter is the plan for nobody. Confirm it by comparing:

EXPLAIN (ANALYZE, BUFFERS) SELECT ... WHERE customer_id = $1;   -- prepared
EXPLAIN (ANALYZE, BUFFERS) SELECT ... WHERE customer_id = 42;  -- literal

The prepared form, once generic, shows a plan that ignores 42's selectivity. The literal shows the index plan. The two outputs side by side are the diagnosis.

The fix, in order

Disable the generic switch for the statement. Setting plan_cache_mode to force_custom_plan for the session or statement makes Postgres plan per execution, which is what EXPLAIN was showing you. The planning cost is paid each time, which is fine for a query whose execution cost dominates.

Use literals for the hot path. If the value is safe to inline, which for an internal integer id it is, executing with a literal bypasses the prepared statement cache entirely. This is a workaround and it reintroduces the care that parameterisation provides, so apply it only where the value is not attacker controlled.

Reduce the skew's blast radius. The generic plan is wrong because one customer's rows dominate. Partitioning or a partial index for the large tenants makes the average plan less wrong, which is a design fix rather than a knob.

Rewrite to make the plan stable. Sometimes the query can be shaped so custom and generic plans coincide, for example by making the selective predicate unambiguous. This is the durable fix when the statement is hot and the skew is permanent.

What I would do differently

I would have asked "is this statement prepared" before "is this query slow", because the question changes the tool. EXPLAIN with a literal shows the custom plan, and is therefore the wrong instrument for a prepared statement complaint. The correct instrument reproduces the production execution mode, prepared with the parameter, so the plan you look at is the plan that runs.

I would also have checked plan cache behaviour as a standard item for any "slow in app, fast in psql" report, because that exact disagreement is its signature. It is the database version of the flag that was read once at boot: the value used at decision time is not the value you are looking at now.

What I now do

A prepared statement's plan is chosen once against the average and then reused without the parameter, so a skewed parameter makes production run a plan that no EXPLAIN with a literal will show you. Reproduce the execution mode before diagnosing, and when the app and the session disagree, the plan cache is the first suspect.

The related silent growth defect, where the plan is right until the data scale changes it, is the query that was fast until the table grew.