Re: BUG #13817: Query planner strange choose while select/count small part of big table - complete

Hi,

Thanks for reply.

First about questions:
- Yes I'have ssd disk but my co-worker has the same base on traditional
disk and behaviour is similar (but 2 times slower).
- It is always slow regardless of repetitions and disks.
- I think default. I didn't change it. Yes it is 4.0.
- After setting random_page_cost to 1.5 - no difference.
- There are result with buffers on:

sequence scan on:

"Aggregate (cost=118063.42..118063.43 rows=1 width=8) (actual
time=2478.105..2478.105 rows=1 loops=1)"
" Buffers: shared hit=401 read=49722"
" -> Hash Join (cost=7.88..108082.13 rows=3992515 width=8) (actual
time=2478.087..2478.091 rows=3 loops=1)"
" Hash Cond: (this_.shipment_order_item_id = orderitem1_.id)"
" Buffers: shared hit=401 read=49722"
" -> Seq Scan on shipment_order_sub_item this_
(cost=0.00..90031.15 rows=3992515 width=16) (actual time=0.081..1134.453
rows=3992110 loops=1)"
" Buffers: shared hit=384 read=49722"
" -> Hash (cost=7.87..7.87 rows=1 width=16) (actual
time=0.151..0.151 rows=3 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 1kB"
" Buffers: shared hit=17"
" -> Hash Semi Join (cost=6.69..7.87 rows=1 width=16)
(actual time=0.143..0.149 rows=3 loops=1)"
" Hash Cond: (orderitem1_.id = oi_.id)"
" Buffers: shared hit=17"
" -> Seq Scan on shipment_order_item orderitem1_
(cost=0.00..1.13 rows=13 width=8) (actual time=0.005..0.006 rows=13
loops=1)"
" Buffers: shared hit=1"
" -> Hash (cost=6.68..6.68 rows=1 width=8) (actual
time=0.122..0.122 rows=3 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 1kB"
" Buffers: shared hit=16"
" -> Nested Loop (cost=0.28..6.68 rows=1
width=8) (actual time=0.059..0.116 rows=3 loops=1)"
" Join Filter: (order1_.user_id =
user2_.users_id)"
" Rows Removed by Join Filter: 9"
" Buffers: shared hit=16"
" -> Nested Loop (cost=0.28..5.59 rows=1
width=16) (actual time=0.047..0.086 rows=3 loops=1)"
" Buffers: shared hit=13"
" -> Nested Loop (cost=0.00..2.29
rows=1 width=24) (actual time=0.026..0.051 rows=3 loops=1)"
" Buffers: shared hit=4"
" -> Seq Scan on
shipment_order_item oi_ (cost=0.00..1.16 rows=1 width=16) (actual
time=0.007..0.011 rows=3 loops=1)"
" Filter: (order_id = 610)"
" Rows Removed by Filter:
10"
" Buffers: shared hit=1"
" -> Seq Scan on shipment_order
order1_ (cost=0.00..1.11 rows=1 width=24) (actual time=0.006..0.006 rows=1
loops=3)"
" Filter: ((id = 610) AND
(court_department_id = ANY ('{1,292,32768}'::bigint[])))"
" Rows Removed by Filter:
6"
" Buffers: shared hit=3"
" -> Index Only Scan using
court_department_pkey on court_department courtdepar3_ (cost=0.28..3.29
rows=1 width=8) (actual time=0.008..0.009 rows=1 loops=3)"
" Index Cond: (department_id =
order1_.court_department_id)"
" Heap Fetches: 3"
" Buffers: shared hit=9"
" -> Seq Scan on application_user user2_
(cost=0.00..1.04 rows=4 width=8) (actual time=0.002..0.003 rows=4 loops=3)"
" Buffers: shared hit=3"
"Planning time: 1.547 ms"
"Execution time: 2478.306 ms"

sequence scan off:

"Aggregate (cost=136819.78..136819.79 rows=1 width=8) (actual
time=1.274..1.274 rows=1 loops=1)"
" Buffers: shared hit=32 read=7"
" -> Nested Loop (cost=1.24..126838.50 rows=3992515 width=8) (actual
time=1.242..1.265 rows=3 loops=1)"
" Buffers: shared hit=32 read=7"
" -> Nested Loop Semi Join (cost=0.81..17.81 rows=1 width=16)
(actual time=1.112..1.119 rows=3 loops=1)"
" Join Filter: (orderitem1_.id = oi_.id)"
" Rows Removed by Join Filter: 33"
" Buffers: shared hit=24 read=4"
" -> Index Only Scan using shipment_order_item_pkey on
shipment_order_item orderitem1_ (cost=0.14..4.83 rows=13 width=8) (actual
time=0.508..0.515 rows=13 loops=1)"
" Heap Fetches: 13"
" Buffers: shared hit=1 read=1"
" -> Materialize (cost=0.67..12.79 rows=1 width=8) (actual
time=0.040..0.044 rows=3 loops=13)"
" Buffers: shared hit=23 read=3"
" -> Nested Loop (cost=0.67..12.78 rows=1 width=8)
(actual time=0.509..0.556 rows=3 loops=1)"
" Buffers: shared hit=23 read=3"
" -> Nested Loop (cost=0.54..9.62 rows=1
width=16) (actual time=0.217..0.253 rows=3 loops=1)"
" Buffers: shared hit=18 read=2"
" -> Nested Loop (cost=0.27..6.32 rows=1
width=24) (actual time=0.198..0.221 rows=3 loops=1)"
" Buffers: shared hit=9 read=2"
" -> Index Scan using
fk_fk_mt3v1s9gl7rr0lo83il8gy00d_idx on shipment_order_item oi_
(cost=0.14..3.15 rows=1 width=16) (actual time=0.129..0.132 rows=3 loops=1)"
" Index Cond: (order_id = 610)"
" Buffers: shared hit=4 read=1"
" -> Index Scan using
shipment_order_pkey on shipment_order order1_ (cost=0.13..3.15 rows=1
width=24) (actual time=0.026..0.027 rows=1 loops=3)"
" Index Cond: (id = 610)"
" Filter: (court_department_id =
ANY ('{1,292,32768}'::bigint[]))"
" Buffers: shared hit=5 read=1"
" -> Index Only Scan using
court_department_pkey on court_department courtdepar3_ (cost=0.28..3.29
rows=1 width=8) (actual time=0.007..0.008 rows=1 loops=3)"
" Index Cond: (department_id =
order1_.court_department_id)"
" Heap Fetches: 3"
" Buffers: shared hit=9"
" -> Index Only Scan using application_user_pkey
on application_user user2_ (cost=0.13..3.15 rows=1 width=8) (actual
time=0.097..0.098 rows=1 loops=3)"
" Index Cond: (users_id = order1_.user_id)"
" Heap Fetches: 3"
" Buffers: shared hit=5 read=1"
" -> Index Scan using fk_fk_rr5k2n8n892ye3uposkh3xp6v_idx on
shipment_order_sub_item this_ (cost=0.43..86895.54 rows=3992515 width=16)
(actual time=0.045..0.046 rows=1 loops=3)"
" Index Cond: (shipment_order_item_id = orderitem1_.id)"
" Buffers: shared hit=8 read=3"
"Planning time: 1.684 ms"
"Execution time: 1.448 ms"

I see that calculated cost is less for seq scan but i don't get how it is
possible if fk_fk_rr5k2n8n892ye3uposkh3xp6v_idx intable
shipment_order_sub_item is on shipment_order_item_id. If I need to pick 8
of 4 millions rows exactly by this index why it is not used and sequence
scan instead? :|. Disabling seq scan works 2216/12=185 times faster.

If it could help I can sent my data base (about 75 MB) on ftp or whenever.

Thanks again.

Regards,
Marcin Sieńko

Pozdrawiam,
Marcin

2015-12-16 17:18 GMT+01:00 Feike Steenbergen <feikesteenbergen(at)gmail(dot)com>:

> Hi,
>
> Looking at the explained plans, it makes sense the seq scan is preferred
> as it is expected to be cheaper.
>
> Seq scan enabled:
> Hash Join (cost=12.88..108087.13 rows=3992515 width=177)
>
> The main costs (83%) of this plan are:
> Seq Scan on shipment_order_sub_item this_ (cost=0.00..90,031.15
> rows=3,992,515 width=125)
>
> Seq scan disabled:
> Nested Loop (cost=1.24..138607.34 rows=3992515 width=177)
>
> The main costs (71%) of this plan are:
> Index Scan using fk_fk_rr5k2n8n892ye3uposkh3xp6v_idx on
> shipment_order_sub_item this_ (cost=0.43..98636.88 rows=3992515 width=125)
>
> The expected costs for the seq scan enabled is 78% of that of the disable
> seq scan.
>
>
>
> Questions:
>
> - What kind of disks do you have (ssd's?)
> - Is the seq scan slow if you repeat it immediately after the first run?
> - What is your current random_page_cost
> - Could you try to reissue the query after lowering the value of
> random_page_cost, like so:
>
> SET random_page_cost TO 1.5;
>
> - Could you redo the explain with
>
> EXPLAIN (ANALYZE ON, BUFFERS ON)
>
> regards,
>
> Feike
>