Re: Missing query plan for auto_explain. - Mailing list pgsql-general

From Matheus Martin
Subject Re: Missing query plan for auto_explain.
Date
Msg-id CAB_m0bHHo1VO7x7i6qZ=uPN0qrzKhbWgCQBBnnw2Zw3tfaS9Zw@mail.gmail.com
Whole thread Raw
In response to Missing query plan for auto_explain.  (Matheus Martin <matheus.martin@voidbridge.com>)
List pgsql-general
The threshold for `auto_explain` was changed to 500 ms and explain plans are still not being logged.

On Tue, 30 Aug 2022 at 13:30, Julien Rouhaud <rjuju123@gmail.com> wrote:
Hi,

On Tue, Aug 30, 2022 at 01:16:43PM +0200, Alvaro Herrera wrote:
> On 2022-Aug-30, Matheus Martin wrote:
>
> > Our Postgres recently started reporting considerably different
> > execution times for the same query. When executed from our JDBC
> > application the Postgres logs report an average execution time of 1500
> > ms but when the query is manually executed through `psql` it doesn't
> > take longer than 50 ms.
>
> I don't know why the plan is not saved by auto_explain (maybe we're
> missing ExecutorEnd calls somewhere?  that would be strange), but one
> frequent reason for queries to show different plan in JDBC than psql is
> the use of prepared statements.  Did you try using "PREPARE
> yourquery(...)" and then EXPLAIN EXECUTE(...)?  Sometimes that helps to
> recreate the original problem.
>
> (Apparently, ExecutorEnd is called from PortalCleanup; what happens with
> the portal for an extended-protocol query?)

AFAICS log_min_duration_statements threshold is based on the full query
processing time while auto_explain is only based on the executor runtime, so
one more likely explanation is that out of the 1423ms, more than 423ms were
spent in the planner?

pgsql-general by date:

Previous
From: Matheus Martin
Date:
Subject: Re: Missing query plan for auto_explain.
Next
From: Alvaro Herrera
Date:
Subject: Re: Missing query plan for auto_explain.