Re: How to observe plan_cache_mode transition from custom to generic plan? - Mailing list pgsql-general
| From | Richard Michael |
|---|---|
| Subject | Re: How to observe plan_cache_mode transition from custom to generic plan? |
| Date | |
| Msg-id | CABR0jEQ3WqqH9_stU3Q90KFHvxU0r_3SsTdWV+byBc25+51A8w@mail.gmail.com Whole thread Raw |
| In response to | How to observe plan_cache_mode transition from custom to generic plan? (Richard Michael <rmichael@edgeofthenet.org>) |
| List | pgsql-general |
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.albe@cybertec.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
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)
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
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
pgsql-general by date: