Re: question on auto_explain

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.