Hi, I was wondering if someone could help us work out why this query is so slow.
We've just dumped a database (Postgresql 9.1) and restored it to a new instance (AWS RDS 9.6) (via pg_dump, restored to psql)
We immediately see that the following fairly straightforward query is now extremely slow with a huge number of shared buffers hit.
On the new instance it takes 25 seconds. On the original system, 0.05 seconds.
The database schemas are both the same (with the same columns indexed) so I'm guessing it must be a configuration issue to make the planner go down a different route.
I have run an analyse on the whole database since restoring.
Also, if on the new instance, I disable indexscans, the query will take 0.047 seconds.
Can someone point us in the right direction on what's going on here?
Query:
explain (buffers,analyse) select
trans_date
from stock_trans s
join account_trans a using(account_trans_id)
where product_id=100
and credit_stock_account_id=3
order by trans_date desc
limit 1;
Bad Performance on New Instance:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.87..9086.72 rows=1 width=4) (actual time=25829.287..25829.287 rows=0 loops=1)
Buffers: shared hit=43944066
-> Nested Loop (cost=0.87..6196547.28 rows=682 width=4) (actual time=25829.286..25829.286 rows=0 loops=1)
Buffers: shared hit=43944066
-> Index Scan Backward using account_trans_date_idx on account_trans a (cost=0.43..392996.60 rows=11455133 width=8) (actual time=0.007..3401.027 rows=11455133 loops=1)
Buffers: shared hit=251082
-> Index Scan using stock_trans_account_trans_idx on stock_trans s (cost=0.43..0.50 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=11455133)
Index Cond: (account_trans_id = a.account_trans_id)
Filter: ((product_id = 2466420) AND (credit_stock_account_id = 3))
Rows Removed by Filter: 1
Buffers: shared hit=43692984
Planning time: 0.271 ms
Execution time: 25829.316 ms
(13 rows)
Disabled indexscan:
=> set enable_indexscan=off;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=11049.80..11049.81 rows=1 width=4) (actual time=0.018..0.018 rows=0 loops=1)
Buffers: shared hit=3
-> Sort (cost=11049.80..11051.51 rows=682 width=4) (actual time=0.017..0.017 rows=0 loops=1)
Sort Key: a.trans_date DESC
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=3
-> Nested Loop (cost=35.99..11046.39 rows=682 width=4) (actual time=0.011..0.011 rows=0 loops=1)
Buffers: shared hit=3
-> Bitmap Heap Scan on stock_trans s (cost=31.59..5301.09 rows=682 width=4) (actual time=0.011..0.011 rows=0 loops=1)
Recheck Cond: (product_id = 2466420)
Filter: (credit_stock_account_id = 3)
Buffers: shared hit=3
-> Bitmap Index Scan on stock_trans_product_idx (cost=0.00..31.42 rows=1465 width=0) (actual time=0.009..0.009 rows=0 loops=1)
Index Cond: (product_id = 2466420)
Buffers: shared hit=3
-> Bitmap Heap Scan on account_trans a (cost=4.40..8.41 rows=1 width=8) (never executed)
Recheck Cond: (account_trans_id = s.account_trans_id)
-> Bitmap Index Scan on account_trans_pkey (cost=0.00..4.40 rows=1 width=0) (never executed)
Index Cond: (account_trans_id = s.account_trans_id)
Planning time: 0.272 ms
Execution time: 0.047 ms
(21 rows)
Explain from the same query on the original database:
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=9811.51..9811.52 rows=1 width=4) (actual time=0.020..0.020 rows=0 loops=1)
Buffers: shared hit=3
-> Sort (cost=9811.51..9813.23 rows=685 width=4) (actual time=0.019..0.019 rows=0 loops=1)
Sort Key: a.trans_date
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=3
-> Nested Loop (cost=0.00..9808.09 rows=685 width=4) (actual time=0.014..0.014 rows=0 loops=1)
Buffers: shared hit=3
-> Index Scan using stock_trans_product_idx on stock_trans s (cost=0.00..3300.01 rows=685 width=4) (actual time=0.014..0.014 rows=0 loops=1)
Index Cond: (product_id = 2466420)
Filter: (credit_stock_account_id = 3)
Buffers: shared hit=3
-> Index Scan using account_trans_pkey on account_trans a (cost=0.00..9.49 rows=1 width=8) (never executed)
Index Cond: (account_trans_id = s.account_trans_id)
Total runtime: 0.050 ms
(15 rows)
Regards,
-- David
