Re: How to observe plan_cache_mode transition from custom to generic plan?

On Sun, 2021-09-05 at 14:20 -0400, Mladen Gogala wrote:
> On 9/5/21 9:35 AM, Richard Michael wrote:
> > TL;DR --
> >
> > 1/ My basic prepared statement doesn't seem to start out with a custom
> > plan
> > (i.e., no parameter symbols in query text).

That is notmal for the first five executions. PostgreSQL will consider a
generic plan only from the sixth execution on.

> > 2/ EXPLAIN EXECUTE of prepared statement doesn't show query text, as the
> > documentation seems to imply.  Should it?

Yes, and it does for me - see below.

> > 3/ How can I observe the effect of plan_cache_mode?
> >     e.g., Possible plan change from custom to generic

By checking for the presence of $1, $2 and the like in the EXPLAIN output.

Here is a sample session that shows all that in action:

PREPARE stmt(integer) AS SELECT * FROM jobs WHERE job_id = $1;

EXPLAIN EXECUTE stmt(1);

QUERY PLAN
═════════════════════════════════════════════════════
Seq Scan on jobs (cost=0.00..1.04 rows=1 width=10)
Filter: (job_id = 1)
(2 rows)

EXPLAIN EXECUTE stmt(2);

QUERY PLAN
═════════════════════════════════════════════════════
Seq Scan on jobs (cost=0.00..1.04 rows=1 width=10)
Filter: (job_id = 2)
(2 rows)

EXPLAIN EXECUTE stmt(3);

QUERY PLAN
═════════════════════════════════════════════════════
Seq Scan on jobs (cost=0.00..1.04 rows=1 width=10)
Filter: (job_id = 3)
(2 rows)

EXPLAIN EXECUTE stmt(4);

QUERY PLAN
═════════════════════════════════════════════════════
Seq Scan on jobs (cost=0.00..1.04 rows=1 width=10)
Filter: (job_id = 4)
(2 rows)

EXPLAIN EXECUTE stmt(5);

QUERY PLAN
═════════════════════════════════════════════════════
Seq Scan on jobs (cost=0.00..1.04 rows=1 width=10)
Filter: (job_id = 5)
(2 rows)

EXPLAIN EXECUTE stmt(6);

QUERY PLAN
═════════════════════════════════════════════════════
Seq Scan on jobs (cost=0.00..1.04 rows=1 width=10)
Filter: (job_id = $1)
(2 rows)

As you see, the sixth execution uses a generic plan.

> > 2/ The query text was logged by `auto_explain`.  However, it contains a
> > parameter symbol; why?  Also, why is the logged query a `PREPARE`
> > statement
> > (as if a new prepared statement is being created), instead of only the
> > `SELECT ..` which was executed?

You saw the log entry for the PREPARE statement. Since your statement
contains $1 in its query text, you'll get that logged.

Look for the log entries for the EXECUTEs.

By the way, here is one of the shortcomings of using prepared statements
in my opinion: if EXECUTE is slow, you will get the EXECUTE logged, but
not the statement text of the prepared statements.

> Well, some other databases that shall remain unnamed have a thing called
> "bind variable peeking". [more off-topic things skipped]

Most of your explanations about PostgreSQL are correct, but:

> Postgres has a different method: it executes the same statement with 5
> different sets of bind variables and if it finds a plan that is cheaper
> than the generic plan, it caches it and uses it in the future.

That is wrong: If the estimate for the generic plan is more expensive
than the plans for the first five executions, it will keep generating a
custom plan for subsequent executions of the prepared statement.

> People switching from Oracle, me being one of those, frequently make
> mistake of using bind variables in Postgres.

"Bind variables" just being an Oraclism for parameters, it is *not* a
mistake to use them in PostgreSQL.

Yours,
Laurenz Albe