1

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"
MatthewAws
  • 13
  • 4
  • Does this answer your question? postgres Poor performance on ORDER BY "id" DESC LIMIT 1 – mustaccio Jan 07 '22 at 17:19
  • 1
    You should do EXPLAIN (ANALYZE, BUFFERS), not just EXPLAIN ANALYZE. – jjanes Jan 07 '22 at 21:06
  • Whatever else may be going on, you seem to have astonishingly bad hardware. 4 seconds for that seq scan? Yikes! – jjanes Jan 07 '22 at 21:07
  • An answer to your side question: Insert-only tables do not get autovac, until v13 where autovacuum_vacuum_insert_threshold was added. But that doesn't address the main problem as vacuuming doesn't help you anyway. They should still get autoanalyzed, but that doesn't help you either, as you suffer from a data dependence that simple stats cannot diagnose. – jjanes Jan 08 '22 at 17:56
  • "a very similar table in my database with very similar data does not suffer from such poor performance" Explaining the difference between two things is much easier if we are allowed to see both of those things. – jjanes Jan 08 '22 at 17:59
  • @jjanes I have provided updated results for EXPLAIN (ANALYZE, BUFFERS) on both tables. – MatthewAws Jan 10 '22 at 06:50

2 Answers2

2

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'
Laurenz Albe
  • 51,298
  • 4
  • 39
  • 69
  • Hi Laurenz, Thanks for the reply. ANALYZE on the table does not have any impact on the query performance. I am not too keen forcing a seq scan, as even that is rather slow (4 seconds) Did you see my updated question where I've presented the performance of a simple query against the refreshed_utc index? – MatthewAws Jan 07 '22 at 16:05
  • @MatthewAws - not entirely sure here (Laurenz?), but would one of the indexes here be better than CREATE INDEX ON customer (refreshed_utc) WHERE purged_utc IS NULL;? – Vérace Jan 07 '22 at 17:39
  • @MatthewAws I didn't suggest to use a sequential scan, but to avoid the slow index scan. Did you try it? – Laurenz Albe Jan 10 '22 at 07:32
  • @Verace I don't think that it is an advantage to include the second column as index key. – Laurenz Albe Jan 10 '22 at 07:33
  • @LaurenzAlbe Not as of yet. I'm limited by the db being run in production and I'm not easily able to copy the data, as it's sensitive by nature.

    I am frequently querying the table on refreshed_utc without the purged_utc. So the index you've suggested would not be utilized in those cases, which means I would have to maintain two separate indexes on refreshed_utc.

    Would it not simply be better to create a composite index instead to cover scenarioes where I am querying with and without purged_utc as a condition?

     – MatthewAws Jan 10 '22 at 07:43
  • Sure, that is an option. It will be a little slower than my suggestion, but probably good enough. – Laurenz Albe Jan 10 '22 at 11:02
1

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.

Erwin Brandstetter
  • 175,982
  • 27
  • 439
  • 600
  • He needs the partial index. The index on (purged_utc, refreshed_utc) does not work. It should, but it doesn't. – jjanes Jan 08 '22 at 17:49
  • @jjanes: Hmm? Because the poor overall selectivity of the first column rules out an index scan? NULL being common overall, and only rare in the time range of the query? We should at least see a bitmap index scan - though that's not nearly as efficient as the index scan on the partial index. Smells like room for improvement in the query planner. – Erwin Brandstetter Jan 08 '22 at 21:36
  • If I make NULL values in purged_tc rare overall, I get an index scan: db<>fiddle here – Erwin Brandstetter Jan 08 '22 at 21:40
  • 1
    But the key in your example is that the planner knows that the purged_utc is very selective. If it doesn't know that, then the planner thinks the "read in order and stop early" feature is critical to good performance out of the index. And for some reason I haven't been able to figure out, the planner is unwilling to believe it can read the 2nd column in order when the first column is tested for IS NULL. That is why the partial is needed. – jjanes Jan 09 '22 at 01:15
  • @jjanes: I see. Thanks for pointing that out. Here's an updated fiddle working out that unexpected sort step (for reference): db<>fiddle here – Erwin Brandstetter Jan 09 '22 at 01:25
  • I am frequently querying the refreshed_utc index independantly of the purged_utc, so I assume that a composite index (refreshed_utc, purged_utc) would be prefered instead. Would it not be better to have a composite index, rather than having to maintain multiple isolated indexes on the table?

    I have updated my question with results of EXPLAIN (ANALYZE, BUFFERS) on both tables, and as you can see there is a major difference between the two. Also in terms of cache-hits.

     – MatthewAws Jan 10 '22 at 07:46
  • @Mat Queries on just refreshed_utc can only make very limited use of a multicolumn index where it's not the leading column. And we'd need purgrd_utc first. See: https://dba.stackexchange.com/a/27493/3684 and https://dba.stackexchange.com/a/33220/3684 – Erwin Brandstetter Jan 10 '22 at 08:33