Search Postgresql Archives

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

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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




[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Index of Archives]     [Postgresql Jobs]     [Postgresql Admin]     [Postgresql Performance]     [Linux Clusters]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Databases]     [Postgresql & PHP]     [Yosemite]

  Powered by Linux