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"
6
  • Does this answer your question? postgres Poor performance on ORDER BY "id" DESC LIMIT 1
    – mustaccio
    Jan 7 at 17:19
  • 1
    You should do EXPLAIN (ANALYZE, BUFFERS), not just EXPLAIN ANALYZE.
    – jjanes
    Jan 7 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 7 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 8 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 8 at 17:59

2 Answers 2

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'
    
6
  • 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 7 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;? Jan 7 at 17:39
  • @MatthewAws I didn't suggest to use a sequential scan, but to avoid the slow index scan. Did you try it? Jan 10 at 7:32
  • @Verace I don't think that it is an advantage to include the second column as index key. Jan 10 at 7: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 at 7:43
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.

7
  • He needs the partial index. The index on (purged_utc, refreshed_utc) does not work. It should, but it doesn't.
    – jjanes
    Jan 8 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. Jan 8 at 21:36
  • If I make NULL values in purged_tc rare overall, I get an index scan: db<>fiddle here Jan 8 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 9 at 1: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 Jan 9 at 1:25

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.