Thread: question on auto_explain

question on auto_explain

From
Karsten Hilbert
Date:
Dear list,

when debugging slow queries in a larger application (https://www.gnumed.de) I started to use auto_explain.

The "normal" EXPLAIN warns

  https://www.postgresql.org/docs/current/sql-explain.html

that ANALYZE on INSERT/UPDATE/DELETE will (of course, in hindsight) modify rows. Now, the
auto_explain docs

  https://www.postgresql.org/docs/current/auto-explain.html

don't explicitely state that it does so, too. Nor can I read impliciteness that
"normal" EXPLAIN is *run* by auto_explain.

Hence my question:

  Does auto_explain also modify rows on INSERT/UPDATE/DELETE if auto_explain.log_analyze is TRUE ?

If not how so ?

(I guess it would have to run a dance of "BEGIN; EXPLAIN ANALYZE ...; ROLLBACK;" just
 before any query is being run.)

Thanks,
Karsten



Re: question on auto_explain

From
"David G. Johnston"
Date:
On Thu, Aug 3, 2023 at 9:29 AM Karsten Hilbert <Karsten.Hilbert@gmx.net> wrote:
  https://www.postgresql.org/docs/current/auto-explain.html

don't explicitely state that it does so, too. Nor can I read impliciteness that
"normal" EXPLAIN is *run* by auto_explain.

auto_explain automatically produces the explain output of a query that is running for reals.  The effect is identical to running explain analyze except your output here is whatever the query would produce instead of the explain output, which instead goes into the log.

David J.

Aw: Re: question on auto_explain

From
Karsten Hilbert
Date:
> On Thu, Aug 3, 2023 at 9:29 AM Karsten Hilbert <Karsten.Hilbert@gmx.net[mailto:Karsten.Hilbert@gmx.net]> wrote:
>>

>>  https://www.postgresql.org/docs/current/auto-explain.html[https://www.postgresql.org/docs/current/auto-explain.html]
>>
>> don't explicitely state that it does so, too. Nor can I read impliciteness that
>> "normal" EXPLAIN is *run* by auto_explain.
>
> auto_explain automatically produces the explain output of a query that is running for reals.  The effect is identical
torunning explain analyze except your output > here is whatever the query would produce instead of the explain output,
whichinstead goes into the log. 

Thanks David. I take this to mean that auto_explain produces the same side-effects as manually running "explain
analyze"does. 

Would this warrant a documentation patch ?  Like so:

  auto_explain.log_analyze causes EXPLAIN ANALYZE output, rather than just EXPLAIN output, to be printed when an
executionplan is logged. Hence 
  the same caveats apply for INSERT/UPDATE/DELETE queries.

Also, doesn't this makes auto_explain.log_analyze = TRUE rather surprising as it
can make any INSERT/UPDATE/DELETE fail when it is slow for some reason ...

Thanks,
Karsten



Aw: Re: question on auto_explain

From
Karsten Hilbert
Date:
> > auto_explain automatically produces the explain output of a query that is running for reals.  The effect is
identicalto running explain analyze except your output > here is whatever the query would produce instead of the
explainoutput, which instead goes into the log. 
>
> Thanks David. I take this to mean that auto_explain produces the same side-effects as manually running "explain
analyze"does. 
>
> Would this warrant a documentation patch ?  Like so:
>
>   auto_explain.log_analyze causes EXPLAIN ANALYZE output, rather than just EXPLAIN output, to be printed when an
executionplan is logged. Hence 
>   the same caveats apply for INSERT/UPDATE/DELETE queries.
>
> Also, doesn't this makes auto_explain.log_analyze = TRUE rather surprising as it
> can make any INSERT/UPDATE/DELETE fail when it is slow for some reason ...

Ah, wait, I think I've been a bit dense here. I thought it was a two-step process of
first running any queries "normally", somehow magically noticing slow ones as per
auto_explain.log_min_duration, and re-running those with EPXPLAIN ANALYZE prepended.

I think I understand better now: with auto_explain ALL queries are run with EXPLAIN ANALYZE
prepended BUT the output is two-fold: query results are fed into whatever wire protocol client
is and EXPLAIN output is re-routed to the log. Does that sound right ?

I think was misguided by psql discarding (?) query results (the rows)
while displaying EXPLAIN output only.

The auto_explain docs might perhaps still benefit from a more
explicit hint towards write query side effects.

Karsten



Re: question on auto_explain

From
Julien Rouhaud
Date:
Hi,

On Thu, Aug 03, 2023 at 09:45:39PM +0200, Karsten Hilbert wrote:
> > > auto_explain automatically produces the explain output of a query that is running for reals.  The effect is
identicalto running explain analyze except your output > here is whatever the query would produce instead of the
explainoutput, which instead goes into the log.
 
> >
> > Thanks David. I take this to mean that auto_explain produces the same side-effects as manually running "explain
analyze"does.
 
> >
> > Would this warrant a documentation patch ?  Like so:
> >
> >   auto_explain.log_analyze causes EXPLAIN ANALYZE output, rather than just EXPLAIN output, to be printed when an
executionplan is logged. Hence
 
> >   the same caveats apply for INSERT/UPDATE/DELETE queries.
> >
> > Also, doesn't this makes auto_explain.log_analyze = TRUE rather surprising as it
> > can make any INSERT/UPDATE/DELETE fail when it is slow for some reason ...
>
> Ah, wait, I think I've been a bit dense here. I thought it was a two-step process of
> first running any queries "normally", somehow magically noticing slow ones as per
> auto_explain.log_min_duration, and re-running those with EPXPLAIN ANALYZE prepended.
>
> I think I understand better now: with auto_explain ALL queries are run with EXPLAIN ANALYZE
> prepended BUT the output is two-fold: query results are fed into whatever wire protocol client
> is and EXPLAIN output is re-routed to the log. Does that sound right ?

That's not how it's implemented but that's the idea.  auto_explain indeed
doesn't run an extra EXPLAIN ..., it simply asks for the wanted instrumentation
data before the execution, and then output the actually used execution plan to
the logs.

> I think was misguided by psql discarding (?) query results (the rows)
> while displaying EXPLAIN output only.

Note that it's not psql discarding the rows but the EXPLAIN command.


> The auto_explain docs might perhaps still benefit from a more
> explicit hint towards write query side effects.

The docs says that it automatically shows the execution plans, not that it's
itself doing an EXPLAIN.  It also mentions that some flags can lead to
noticeable performance drop as they are influencing all queries even if they
don't reach the configured thresholds so it should be a strong hint about not
having some extra command run.

Now, there also seems to be some common misconception about how auto_explain is
working, as it's not the first time that I hear people thinking or assuming
that it's executing extra EXPLAIN commands.  Maybe adding some extra
clarification could help, maybe stating that the emitted plan is the one
actually used during the query execution.



Re: question on auto_explain

From
Frédéric Yhuel
Date:

On 8/4/23 07:33, Julien Rouhaud wrote:
> Now, there also seems to be some common misconception about how auto_explain is
> working, as it's not the first time that I hear people thinking or assuming
> that it's executing extra EXPLAIN commands.  Maybe adding some extra
> clarification could help, maybe stating that the emitted plan is the one
> actually used during the query execution.

I couldn't agree more. The "two-step process" mentioned by Karsten is a 
common belief among many people, including experienced PostgreSQL DBAs.



Re: question on auto_explain

From
Karsten Hilbert
Date:
Am Fri, Aug 04, 2023 at 01:33:19PM +0800 schrieb Julien Rouhaud:

> > explicit hint towards write query side effects.
>
> The docs says that it automatically shows the execution plans, not that it's
> itself doing an EXPLAIN.

Yep, so maybe _that_ point warrants being pointed out: that
auto_explain *doesn't* suffer from plain EXPLAIN write-query
"side effects" because it instruments normally-run queries
and just outputs to the log extra information (the plans).

Karsten
--
GPG  40BE 5B0E C98E 1713 AFA6  5BC0 3BEA AC80 7D4F C89B