CODEWITHSUNDEEP
postgresqlquery-optimizationexplain
Monika Yadav
Monika Yadav

Reputation: 381

Why Postgres is taking so much time in index only scan

Postgres Version:12

Query:

EXPLAIN (ANALYZE TRUE, VERBOSE TRUE, COSTS TRUE, BUFFERS TRUE, TIMING TRUE) SELECT MIN("id"), MAX("id") FROM "public"."hotel_slot_inventory" WHERE ( "updated_at" >= '2021-03-02 13:30:03' AND "updated_at" < '2021-03-03 06:15:19.127884' );

Query Plan:

 Result  (cost=512.17..512.18 rows=1 width=8) (actual time=65556.920..65556.926 rows=1 loops=1)
   Output: $0, $1
   Buffers: shared hit=370 read=454012 written=8
   I/O Timings: read=62266.717 write=0.194
   InitPlan 1 (returns $0)
     ->  Limit  (cost=0.57..256.09 rows=1 width=4) (actual time=65251.998..65252.001 rows=1 loops=1)
           Output: hotel_slot_inventory.id
           Buffers: shared hit=1 read=453546 written=8
           I/O Timings: read=61967.042 write=0.194
           ->  Index Only Scan using hotel_slot_inventory_id_updated_at_idx on public.hotel_slot_inventory  (cost=0.57..3291347.07 rows=12881 width=4) (actual time=65251.996..65251.997 rows=1 loops=1)
                 Output: hotel_slot_inventory.id
                 Index Cond: ((hotel_slot_inventory.id IS NOT NULL) AND (hotel_slot_inventory.updated_at >= '2021-03-02 13:30:03'::timestamp without time zone) AND (hotel_slot_inventory.updated_at < '2021-03-03 06:15:19.127884'::timestamp without time zone))
                 Heap Fetches: 1
                 Buffers: shared hit=1 read=453546 written=8
                 I/O Timings: read=61967.042 write=0.194
   InitPlan 2 (returns $1)
     ->  Limit  (cost=0.57..256.09 rows=1 width=4) (actual time=304.902..304.903 rows=1 loops=1)
           Output: hotel_slot_inventory_1.id
           Buffers: shared hit=369 read=466
           I/O Timings: read=299.674
           ->  Index Only Scan Backward using hotel_slot_inventory_id_updated_at_idx on public.hotel_slot_inventory hotel_slot_inventory_1  (cost=0.57..3291347.07 rows=12881 width=4) (actual time=304.899..304.899 rows=1 loops=1)
                 Output: hotel_slot_inventory_1.id
                 Index Cond: ((hotel_slot_inventory_1.id IS NOT NULL) AND (hotel_slot_inventory_1.updated_at >= '2021-03-02 13:30:03'::timestamp without time zone) AND (hotel_slot_inventory_1.updated_at < '2021-03-03 06:15:19.127884'::timestamp without time zone))
                 Heap Fetches: 3892
                 Buffers: shared hit=369 read=466
                 I/O Timings: read=299.674
 Planning Time: 0.229 ms
 Execution Time: 65556.982 ms
(28 rows)

We can see that this simple index only scan took 65556.982 ms. Majority of time is taken by InitPlan 1 65251.997 ms.. why so?. it just had to fetch the first record from btree index forward and backward search respectively, as query is asking for Min and Max... not needed to fetch all the matching records from btree index
FYI: Vacuum didn't helped much.

Edit Index Bloat Details:

real_size: 3751411712 = 3.49 GB

extra_size: 470237184 = 448 MB

extra_ratio:12.53

fillfactor: 90

bloat_size: 107053056 = 102 MB

bloat_ratio:2.85

Table Bloat Size: bloat_size: 475283456 = 453 MB

bloat_ratio: 5.088

Upvotes: 0

Views: 805

Answers (1)

jjanes
jjanes

Reputation: 44383

Your index must be leading with (id, updated_at...). Note that this index cannot read merely the time range in question, because that is not the first column in the index, and the column that is first is not specified by equality. So you start scanning the entire index until you find a row that meets the time condition. I call this an in-index filter. Evidently this took a lot of scanning in the forward direction, and that would be because none of the records at that end of the index meet the time condition. The planner, however, doesn't understand this fact, it thinks it will find the 12881 rows scattered evenly throughout the index. Not all at one end of it.

Unlike a regular (out of index) filter, the plan doesn't report on how many rows were evaluated and then removed by an in-index filter. That leaves the plans a bit hard to interpret.

There are two pieces of evidence for this interpretation. One is that the limit nodes exist at all even though you're query doesn't specify a limit. That can only be in support of the min and max aggregates. The other is the injection of IS NOT NULL in the index condition when that was not in your query. I don't know why it does that, but it does indicate an in-index filter (or sometimes a partial index) rather than ordinary index usage.

Upvotes: 1

Related Questions