Re: Query hitting empty tables taking 48 minutes

> On Jun 7, 2018, at 4:58 PM, David G. Johnston <david(dot)g(dot)johnston(at)gmail(dot)com> wrote:
>
> On Thu, Jun 7, 2018 at 3:02 PM, Robert Creager <robert(at)logicalchaos(dot)org <mailto:robert(at)logicalchaos(dot)org>> wrote:
> ​[...]​
> job_id | f | 1 | cc54ca5d-0dca-4b35-acd9-e0fe69c6b247
>
> IIUC, the system believes​ your job_entry table has 300k records ALL of them having the UUID value ending in "*b247" - so it is unsurprising that it chooses to sequentially scan job_entry when its given that ID to search for. And if its given a different ID is realizes it can accurately confirm the absence of the supplied value in the table by using the index.

Yes, I agree. And this explain execution time is fine. It’s the ’same’ query running in the app for 43 minutes at a shot on the same tables that’s giving me heartburn.

> I would suspect that vacuuming these tables would solve your problem. Whether there is an issue beyond a lack of vacuuming, or related to auto-vacuum, I am unsure. Though at this point it may take a vacuum full to recover back to a sane state. Though ANALYZE by itself should clear up the statistical discrepancy.

Auto-vacuum is on, and I was thinking the same re VACUUM fixing it, but, it seems there may be a deeper problem here, hence calling in the people who know things :-)

autovacuum_vacuum_threshold = 5000 # min number of row updates before vacuum
autovacuum_analyze_threshold = 5000 # min number of row updates before
autovacuum_vacuum_scale_factor = 0.1 # fraction of table size before vacuum
autovacuum_analyze_scale_factor = 0.05 # fraction of table size before analyze

(Auto)Vacuum was run (no analyze) ~4.5 hours ago (if this query is correct), but maybe another should of been triggered?

SELECT
*,
n_dead_tup > av_threshold AS "av_needed",
CASE WHEN reltuples > 0
THEN round(100.0 * n_dead_tup / (reltuples))
ELSE 0 END AS pct_dead
FROM (SELECT
N.nspname,
C.relname,
pg_stat_get_tuples_inserted(C.oid) AS n_tup_ins,
pg_stat_get_tuples_updated(C.oid) AS n_tup_upd,
pg_stat_get_tuples_deleted(C.oid) AS n_tup_del,
pg_stat_get_live_tuples(C.oid) AS n_live_tup,
pg_stat_get_dead_tuples(C.oid) AS n_dead_tup,
C.reltuples AS reltuples,
round(current_setting('autovacuum_vacuum_threshold') :: INTEGER + current_setting('autovacuum_vacuum_scale_factor') :: NUMERIC * C.reltuples) AS av_threshold,
date_trunc('minute', greatest(pg_stat_get_last_vacuum_time(C.oid), pg_stat_get_last_autovacuum_time(C.oid))) AS last_vacuum,
date_trunc('minute', greatest(pg_stat_get_last_analyze_time(C.oid), pg_stat_get_last_analyze_time(C.oid))) AS last_analyze
FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace)
WHERE C.relkind IN ('r', 't') AND N.nspname NOT IN ('pg_catalog', 'information_schema') AND N.nspname !~ '^pg_toast') AS av
WHERE reltuples > 0
ORDER BY av_needed DESC, n_dead_tup DESC;

nspname relname n_tup_ins n_tup_upd n_tup_del n_live_tup n_dead_tup reltuples av_threshold last_vacuum last_analyze av_needed pct_dead
ds3 job_entry 303658 815 303658 0 300022 300022 35002 2018-06-07 23:09:00.000000 NULL true 100

> But, I may be missing something, my experience and skill here is somewhat limited.

Ditto, at this level.

Best,
Robert