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 Jl. Pura Mertasari No. 7, Sunset Road Abian Base Kuta, Badung – Bali 80361, Indonesia |