Thread: question on auto_explain
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
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.
> 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
> > 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
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.
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.
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