Slow planning, fast execution for particular 3-table query

We’re having trouble working out why the planning time for this particular query is slow (~2.5s vs 0.9ms execution time). As you can see below, there are only 3 tables involved so it’s hard to imagine what decisions the planner has to make that take so long. After 5 runs the prepared-statement code kicks in and it becomes quick, but it’s quite infuriating for the first 5 runs given the execution is so much faster.

Are you able to give any tips what might be taking so long (and how we might improve it)?

We read elsewhere that someone had a “catalog stats file leak”, which I’m taking to mean a big pg_statistic table. Ours is 10mb, which doesn’t seem particularly large to me, but I don’t have much context for it. https://www.postgresql.org/message-id/CABWW-d21z_WgawkjXFQQviqm16oAx0KQvR6bLkRxvYQmhdByfg%40mail.gmail.com

Other queries (with 3 or more tables) in the same db seem to be planning much quicker.

The query:

explain (analyse) SELECT subscription_binding.subscription_binding,
subscription_binding.tid,
subscription.subscription_uuid,
subscription_binding.subscription_binding_uuid,
binding.binding_uuid,
subscription_binding.start_time,
subscription_binding.end_time,
subscription_binding.timezone,
now() >= subscription_binding.start_time AND (subscription_binding.end_time IS NULL OR now() <= subscription_binding.end_time) AS active
FROM jackpot.binding
JOIN jackpot.subscription_binding USING (tid, binding)
JOIN jackpot.subscription USING (tid, subscription)
where (tid=2082003407) AND (binding_uuid='4f61dcd5-97a0-4098-b9ae-c1546c31b2e6'::uuid) offset 0 limit 1000;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=1.29..25.38 rows=1 width=80) (actual time=0.770..0.771 rows=1 loops=1)
-> Nested Loop (cost=1.29..25.38 rows=1 width=80) (actual time=0.770..0.771 rows=1 loops=1)
-> Nested Loop (cost=0.86..16.91 rows=1 width=76) (actual time=0.697..0.698 rows=1 loops=1)
-> Index Scan using binding_tid_binding_uuid_key on binding (cost=0.43..8.45 rows=1 width=28) (actual time=0.647..0.647 rows=1 loops=1)
Index Cond: ((tid = 2082003407) AND (binding_uuid = '4f61dcd5-97a0-4098-b9ae-c1546c31b2e6'::uuid))
-> Index Scan using subscription_binding_idx on subscription_binding (cost=0.43..8.45 rows=1 width=64) (actual time=0.045..0.046 rows=1 loops=1)
Index Cond: ((tid = 2082003407) AND (binding = binding.binding))
-> Index Scan using subscription_pkey on subscription (cost=0.43..8.45 rows=1 width=28) (actual time=0.068..0.068 rows=1 loops=1)
Index Cond: ((tid = 2082003407) AND (subscription = subscription_binding.subscription))
Planning time: 2429.682 ms
Execution time: 0.914 ms
(11 rows)

Postgres version 9.5.19

Each of the tables has between 3-4 indexes, and all the indexes include tid as first parameter. No partitions, no sign of a stray replication slot / uncommitted transaction / prepared transaction that may be holding up autovac, no sign of bloated indexes.

TIA!

Best regards,

David Wheeler
General Manager Bali Office
Bali T +62 361 475 2333 M +62 819 3660 9180
E dwheeler(at)dgitsystems(dot)com<mailto:dwheeler(at)dgitsystems(dot)com>
Jl. Pura Mertasari No. 7, Sunset Road Abian Base
Kuta, Badung – Bali 80361, Indonesia
http://www.dgitsystems.com<http://www.dgitsystems.com/>

[signature_1605257152][signature_1263573595]