Re: Random slow queries

On 29 June 2016 at 16:32, Igor Neyman <ineyman@perceptron.com> wrote:
> Did you try AUTO_EXPLAIN extension
> (https://www.postgresql.org/docs/9.3/static/auto-explain.html) for
> diagnostic purposes?
> With auto_explain.loganalize = true it will log automatically EXPLAIN
> ANALYZE output, rather than just EXPLAIN output.  Turning this parameter ON
> permanently could have negative impact on over-all performance, so use it
> judiciously.
>
> Regards,
> Igor
>

Yes, I tried that. As mentioned in my original email:
> Things I tried:
> ...
> - Enable auto_explain to obtain more information. Unfortunately, for the
> 2-minute queries no plan is logged. If I manually force a query to take a
> long time (eg SELECT pg_sleep(5)) or if I set auto_explain.log_min_duration
> low enough plans are logged for slow queries, _except_ for these 2-minute
> mysteries. This makes it very hard to see exactly why the query is taking so
> long. Is this a bug in auto_explain? Are cached plans never logged (this is
> not indicated in the documentation)? Some other reason why no plan would be
> logged? Note that this happens both in PostgreSQL 9.3.4 and 9.5.3

To be more precise, this is the config I used for auto_explain:
shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = 2000
auto_explain.log_analyze = true
auto_explain.log_buffers = true
auto_explain.log_timing = true

On a test query (eg using pg_sleep) there is logging for both the slow query
log and for auto_explain; for my actual problem queries there's only the slow
query log output, no auto_explain query plan.
As you can see from the logs I posted, it appears the execution plan was
cached (LOG:  duration: 122006.000 ms  bind cached-1453392550: select....).
Maybe those aren't processed by auto_explain?

Best regards,
Roel