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?
