Postgres version: 12.7
Table definition:
column_name, data_type, is_nullable
"id", "integer", "NO"
"data", "jsonb", "NO"
"refreshed_utc","timestamp without time zone", "YES"
"purged_utc", "timestamp without time zone", "YES"
Index definitions:
"customer" "index_purged_utc" "CREATE INDEX index_purged_utc ON public.customer USING btree (purged_utc)"
"customer" "index_refreshed_utc" "CREATE INDEX index_refreshed_utc ON public.customer USING btree (refreshed_utc)"
"customer" "pkey_id" "CREATE UNIQUE INDEX pkey_id ON public.customer USING btree (id)"
Cardinality:
Total table rows: 930615
Table rows where purged_utc is null: 773033
Table rows where purged_utc is null & refreshed_utc < '2021-07-11 00:00:00': 554
Queries to analyze:
With refreshed_utc < '2021-07-11 00:00:00' condition, sorting and limit
EXPLAIN ANALYZE
SELECT *
FROM public.customer
WHERE refreshed_utc < '2021-07-11 00:00:00'
ORDER BY refreshed_utc LIMIT 10
Result:
"Limit (cost=0.42..26.83 rows=10 width=1225) (actual time=1.567..3.174 rows=10 loops=1)"
" -> Index Scan using index_refreshed_utc on customer (cost=0.42..412819.81 rows=156368 width=1225) (actual time=1.566..3.171 rows=10 loops=1)"
" Index Cond: (refreshed_utc < '2021-07-11 14:12:01.073442'::timestamp without time zone)"
"Planning Time: 0.113 ms"
"Execution Time: 3.235 ms"
With both conditions (without sorting and limit)
EXPLAIN ANALYZE
SELECT *
FROM public.customer
WHERE purged_utc is NULL AND refreshed_utc < '2021-07-11 00:00:00'
Result:
"Seq Scan on customer (cost=0.00..175715.76 rows=130062 width=1225) (actual time=1587.866..4089.368 rows=554 loops=1)"
" Filter: ((purged_utc IS NULL) AND (refreshed_utc < '2021-07-11 00:00:00'::timestamp without time zone))"
" Rows Removed by Filter: 930100"
"Planning Time: 0.079 ms"
"Execution Time: 4089.539 ms"
With both conditions, sorting & limit:
EXPLAIN ANALYZE
SELECT *
FROM public.customer
WHERE purged_utc is NULL AND refreshed_utc < '2021-07-11 00:00:00'
ORDER BY refreshed_utc LIMIT 10
Result:
"Limit (cost=0.42..32.16 rows=10 width=1225) (actual time=47783.313..47786.324 rows=10 loops=1)"
" -> Index Scan using index_refreshed_utc on customer (cost=0.42..412815.81 rows=130062 width=1225) (actual time=47783.312..47786.319 rows=10 loops=1)"
" Index Cond: (refreshed_utc < '2021-07-11 00:00:00'::timestamp without time zone)"
" Filter: (purged_utc IS NULL)"
" Rows Removed by Filter: 157611"
"Planning Time: 0.160 ms"
"Execution Time: 47787.474 ms"
I have a really hard time understanding why the query including both conditions as well as the order and limit is so slow. I can see that it's using one of the indexes and then a filter afterwards (purged_utc IS NULL) on what I assume is the initial result of the index scan.
I am hoping someone can shed some light on the following:
- What might cause this poor query performance?
- There has not been run any automatic vacuum's on this table since it was established. Could this be causing such long query times?
- The seq scan is more than 10 times as fast in this case - could this indicate a need for vacuum/reindex?
- Why does the EXPLAIN ANALYZE indicate in the actual cost, that the Index scan didn't start until: 47783.313?
- I considered creating a composite index on purged_utc and refreshed_utc, but what I find really strange in this scenario, is that a very similar table in my database with very similar data does not suffer from such poor performance even with identical queries.
UPDATE: Examples of EXPLAIN (ANALYZE, BUFFERS)
"Limit (cost=0.42..31.20 rows=10 width=12) (actual time=43902.933..43904.053 rows=10 loops=1)"
" Buffers: shared hit=10270 read=140259 dirtied=39"
" I/O Timings: read=43189.074"
" -> Index Scan using index_refreshed_utc on customer (cost=0.42..424916.75 rows=138059 width=12) (actual time=43902.931..43904.047 rows=10 loops=1)"
" Index Cond: (refreshed_utc < '2021-07-14 14:12:01.073442'::timestamp without time zone)"
" Filter: (purged_utc IS NULL)"
" Rows Removed by Filter: 156538"
" Buffers: shared hit=10270 read=140259 dirtied=39"
" I/O Timings: read=43189.074"
"Planning Time: 0.103 ms"
"Execution Time: 43904.125 ms"
As suggested I will also provide the result of a different database table that is identical in terms of schema except namings and the content of the jsonb column:
"Limit (cost=0.43..30.47 rows=10 width=12) (actual time=737.129..737.158 rows=10 loops=1)"
" Buffers: shared hit=158584 read=32362 written=4"
" I/O Timings: read=141.067 write=0.136"
" -> Index Scan using index_refreshed_utc on account (cost=0.43..526833.80 rows=175353 width=12) (actual time=737.127..737.155 rows=10 loops=1)"
" Index Cond: (refreshed_utc < '2021-07-14 14:12:01.073442'::timestamp without time zone)"
" Filter: (purged_utc IS NULL)"
" Rows Removed by Filter: 214764"
" Buffers: shared hit=158584 read=32362 written=4"
" I/O Timings: read=141.067 write=0.136"
"Planning Time: 0.096 ms"
"Execution Time: 737.217 ms"
EXPLAIN (ANALYZE, BUFFERS)
, not just EXPLAIN ANALYZE.