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

Hi Laurenz,

Thank you for the quick response and clear demonstration. I have a few
comments, inline below.

On Mon, Sep 6, 2021 at 8:26 AM Laurenz Albe <laurenz(dot)albe(at)cybertec(dot)at>
wrote:

> 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.
>

Yes, I understood from the documentation that I should expect the sixth
query to be generic. My comment was perhaps awkwardly phrased in the
negative-- I wondered why I was *not* seeing a custom query as the first
planned (indeed, first five), that is: one with substituted literals, not
placeholders.

I misunderstood that parameters only appear (either subtituted or as
placeholders, $1, etc.) in portions of the query *plan* output (for
example, "Filter:" and "Output:" lines). I overlooked that even my basic
query had a plan containing "Output: $1" on the sixth EXPLAIN EXECUTE.

Briefly:

PREPARE basic(int) AS SELECT $1 AS number;
EXPLAIN EXECUTE basic(10);
... Output: 10

-- Repeat 4 more times, then:

EXPLAIN EXECUTE basic(10);
... Output: $1

> > > 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.
>

I do not see the query text in your EXPLAIN EXECUTE output. Perhaps I am
misusing terminology?

By "query text", I mean-- I do not see: "SELECT * FROM jobs WHERE job_id =
1" (in the case of a custom plan), or "... job_id = $1" (in the case of a
generic query).

(I do, of course, see the substituted parameter value (1, 2, 3, etc. for $1
as job_id) on various lines, and thanks again for the quick demo.)

> > > 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.
>

In my log (with auto_explain enabled), even for EXPLAIN EXECUTE, the plan
shows the query text as: PREPARE ...

In my initial post, I was trying to describe that I expected "EXPLAIN
EXECUTE foo('red')" to log, without "PREPARE ..." prefixed, e.g.,
Query Text: SELECT * FROM data WHERE colour = $1

Here is my psql session, interspersed with the postgres.log content:

~# PREPARE foo(text) AS SELECT * FROM data WHERE colour = $1 LIMIT 1;
PREPARE

2021-09-09 16:29:51.235 CEST [3680] LOG: statement: PREPARE foo(text) AS
SELECT * FROM data WHERE colour = $1 LIMIT 1;
2021-09-09 16:29:51.236 CEST [3680] LOG: duration: 0.840 ms

~# EXPLAIN EXECUTE foo('red');
QUERY PLAN
----------------------------------------------------------------------
Limit (cost=0.00..0.04 rows=1 width=46)
-> Seq Scan on data (cost=0.00..109229.00 rows=2500000 width=46)
Filter: (colour = 'red'::text)
(3 rows)

2021-09-09 16:31:17.782 CEST [3680] LOG: statement: EXPLAIN EXECUTE
foo('red');
2021-09-09 16:31:17.783 CEST [3680] LOG: duration: 0.000 ms plan:
Query Text: PREPARE foo(text) AS SELECT * FROM data WHERE colour =
$1 LIMIT 1; <==== Why "PREPARE ...", not just "SELECT ..." ?
Limit (cost=0.00..0.04 rows=1 width=46)
Output: id, md5sum, colour
-> Seq Scan on public.data (cost=0.00..109229.00 rows=2490000
width=46)
Output: id, md5sum, colour
Filter: (data.colour = 'red'::text)
2021-09-09 16:31:17.783 CEST [3680] LOG: duration: 1.390 ms

Thanks again Laurenz, now I know what to look for in the output and logs.

Regards,
Richard

> 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
>
>
>
>