8
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS)  
SELECT * 
FROM contract  
WHERE contract.id = 33129;
Index Scan using contract_pkey on public.contract  (cost=0.29..8.31 rows=1 width=305) (actual time=0.121..30.386 rows=1 loops=1)
  Output: id, network, address, platform_id, sync_marker, props, sync_marker_alt, interface, ingested_at, data
  Index Cond: (contract.id = 33129)
  Buffers: shared hit=325
Planning Time: 0.098 ms
Execution Time: 30.412 ms
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS)  
SELECT * 
FROM contract  
WHERE contract.id = 33128;
Index Scan using contract_pkey on public.contract  (cost=0.29..8.31 rows=1 width=305) (actual time=0.020..0.021 rows=1 loops=1)
  Output: id, network, address, platform_id, sync_marker, props, sync_marker_alt, interface, ingested_at, data
  Index Cond: (contract.id = 33128)
  Buffers: shared hit=3
Planning Time: 0.092 ms
Execution Time: 0.040 ms

Note the huge difference in query time. The only hint in the analyse output seem to be shared hits.

This is entirely reproducible and happens every time. The table has about 60.000 rows only. There are other things going on on this production db, so I am thinking that there is some lock contention for this particular row? But I'm not sure how to verify that.

Edit: Querying only a single field exhibits the same problem (though now the output gives me "Heap Fetches" as well):

Index Only Scan using contract_pkey on public.contract  (cost=0.29..8.31 rows=1 width=4) (actual time=0.122..45.477 rows=1 loops=1)
  Output: id
  Index Cond: (contract.id = 33129)
  Heap Fetches: 333
  Buffers: shared hit=326
Planning Time: 0.101 ms
Execution Time: 45.499 ms
Index Only Scan using contract_pkey on public.contract  (cost=0.29..8.31 rows=1 width=4) (actual time=0.025..0.026 rows=1 loops=1)
  Output: id
  Index Cond: (contract.id = 33128)
  Heap Fetches: 1
  Buffers: shared hit=4
Planning Time: 0.103 ms
Execution Time: 0.047 ms

VACUUM contract;

does not change anything.

4
  • 2
    When was the table last vacuumed? Is (was) the row with id = 33129 being updated more frequently than the other one, by chance?
    – mustaccio
    Nov 20, 2021 at 13:47
  • @mustaccio yes, that row was updated much more frequently. A regular VACUUM (not full) as not effect though.
    – miracle2k
    Nov 20, 2021 at 13:50
  • Some of these tables/rows do accumulate a lot of updates over time; I thought that a VACUUM FULL is only required to recover free space. I might have to reconsider my approach. If you have a more detailed explanation handy, I'd love to learn more about why the row updates cause this issue.
    – miracle2k
    Nov 20, 2021 at 14:01
  • See this for example.
    – mustaccio
    Nov 20, 2021 at 15:36

1 Answer 1

13
Buffers: shared hit=325

That means that you had to process 325 8kB pages to find your matching row.

The most likely explanation is that there have been lots of updates on the row with id = 33129, and autovacuum hasn't cleaned them up yet, so there are loads of index entries with id = 33129, and the index scan has to visit all those row versions in the table to determine if it can see them or not.

The problem should go away after a

VACUUM contract;

which should remove dead row versions.

If it doesn't, you have a long running transaction, a stale replication slot or a prepared transaction blocking VACUUM progress, and you should get that fixed.

If VACUUM helps, perhaps you should reduce autovacuum_vacuum_scale_factor for that table so that it receives autovacuum runs more often.

To reduce the need for VACUUM in the face of many UPDATEs, try to get HOT updates.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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