Postgres slow query on nullable index

Question

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"

Answer 1

The database chooses to use an index scan to find the rows in the correct sort order quickly, but it has to scan and discard more rows than it reckons with.

If a simple ANALYZE of the table does not do the trick, you have two options:

• create the perfect index:

  CREATE INDEX ON customer (refreshed_utc) WHERE purged_utc IS NULL;
  

• force PostgreSQL to avoid that index scan by using

  ORDER BY refreshed_utc + INTERVAL '00:00:00'
  

Answer 2

Why does the EXPLAIN ANALYZE indicate in the actual cost, that the Index scan didn't start until: 47783.313?

47783.313 ms is not the time until "the index scan starts". It's the measured "start-up cost", the time until the first row is returned. 157611 rows are thrown away after checking the heap tuple (Rows Removed by Filter: 157611). The manual:

Estimated start-up cost. This is the time expended before the output phase can begin, e.g., time to do the sorting in a sort node.

Expensive either way, but if that jsonb column is big (and not big enough to be mostly "TOAST"ed), Postgres has to read many heap pages in vain.

Either that, and/or you have additional issues with your setup (apart from the sub-optimal index) to explain the surprisingly poor performance. Hardware, server-configuration, not enough resources, excessive table & index bloat?

EXPLAIN (ANALYZE, BUFFERS) instead of just EXPLAIN ANALYZE would be more insightful there.

Data distribution is very unfavorable for your query as only very few rows with purged_utc is null are older than 2021-07-11 (554 out of 773033). As there are many more overall, and because of that small LIMIT 10, Postgres falsely expects to find enough qualifying rows much more quickly, walking the index.

The partial index Laurenz suggested will save most of the time wasted for the query at hand.

Update:
A bigger, but more versatile index on (purged_utc, refreshed_utc) (with leading purged_utc) should also work, but doesn't give us the faster index scan. See comments.