Query time of fetching a particular, single row id by PK is extremely slow

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 c

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.

StackExchange Database Administrators Q#302917, answer score: 13