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

Question

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.

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 '21 at 13:47
@mustaccio yes, that row was updated much more frequently. A regular VACUUM (not full) as not effect though. — miracle2k, Nov 20 '21 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 '21 at 14:01

Laurenz Albe · Accepted Answer · 2021-11-22T11:52:46.467

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.

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

1 Answers1