Re: Missing query plan for auto_explain.

From: Matheus Martin <matheus(dot)martin(at)voidbridge(dot)com>
To: Maxim Boguk <maxim(dot)boguk(at)gmail(dot)com>
Cc: pgsql-general(at)postgresql(dot)org
Subject: Re: Missing query plan for auto_explain.
Date: 2022-09-08 10:17:54
Message-ID: CAB_m0bHf8wGboegycmOceyk+-5CFmPSFLXxQOTwwgYkGX1q=uQ@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

We do have JIT enabled `jit=on` with `jit_above_cost=100000`.

I am sorry but I don't quite understand what role JIT plays in
this situation with `auto_explain`. Could you please elaborate on that?

On Tue, 6 Sept 2022 at 00:29, Maxim Boguk <maxim(dot)boguk(at)gmail(dot)com> wrote:

>
>
> 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 hubert depesz lubaczewski 2022-09-08 12:41:29 Re: [BeginnerQuestion]Why these is 6 rows in my SELECT statement?
Previous Message Ian Lawrence Barwick 2022-09-08 09:02:05 Re: [BeginnerQuestion]Why these is 6 rows in my SELECT statement?