Re: Missing query plan for auto_explain.

From: Maxim Boguk <maxim(dot)boguk(at)gmail(dot)com>
To: Matheus Martin <matheus(dot)martin(at)voidbridge(dot)com>
Cc: pgsql-general(at)postgresql(dot)org
Subject: Re: Missing query plan for auto_explain.
Date: 2022-09-05 23:28:57
Message-ID: CAK-MWwSWzTdV-L-sbFt6gwT35ibBHAqSGuSJAPo2xbJ-1RvqXw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

On Tue, Aug 30, 2022 at 1:38 PM Matheus Martin <
matheus(dot)martin(at)voidbridge(dot)com> 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.
>
> With a view to investigate discrepancies in the plan we enabled `auto_explain` in `session_preload_libraries` with `auto_explain.log_min_duration = '1s'`. All application servers were bounced to ensure new connections were created and picked up the changes. However this trouble query does not have an explain plan printed, even when its execution time exceeds the threshold (other queries do though).
>
> Does anyone have ideas of why the explain plan is not being printed?
>
> Sample log entry for trouble query executed from application:
> ```
> Aug 26 09:11:33 db-931 postgres[8106]: [66-1] 2022-08-26 09:11:33 GMT [8106]: [5-1] db=betwave,user=betwave_app_readonly_user LOG: duration: 1423.481 ms bind <unnamed>:
>
>
My understanding of how to auto_explain work - it deals only for execution
calls, but in your case duration: 1423.481 ms on BIND call, before query
execution.
At least in my understanding - auto_explain cannot work and will not help
in case of a slow BIND call (because it's a time when the query is planned
but not executed).
According documentation:
"Query planning typically occurs when the Bind message is processed. If the
prepared statement has no parameters, or is executed repeatedly, the server
might save the created plan and re-use it during subsequent Bind messages
for the same prepared statement."
Hard to say what the reason for slow planning, but one (there could be
others) likely reason is JIT work. Do you have JIT enabled?

--
Maxim Boguk
Senior Postgresql DBA
https://dataegret.com/

Phone UA: +380 99 143 0000
Phone AU: +61 45 218 5678

LinkedIn: http://www.linkedin.com/pub/maksym-boguk/80/b99/b1b
Skype: maxim.boguk

"Доктор, вы мне советовали так не делать, но почему мне по-прежнему больно
когда я так делаю ещё раз?"

In response to

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Jeffrey Walton 2022-09-06 02:40:02 Changing the admin/postgres user password
Previous Message Ajin Cherian 2022-09-05 14:18:30 Re: Support logical replication of DDLs