Re: Query hitting empty tables taking 48 minutes

[Robert Creager <robert@xxxxxxxxxxxxxxxx>]

On Jun 7, 2018, at 4:58 PM, David G. Johnston <david.g.johnston@xxxxxxxxx> wrote:

On Thu, Jun 7, 2018 at 3:02 PM, Robert Creager <robert@xxxxxxxxxxxxxxxx> 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