Thread: Why query plan is different?

Hi,<br /> Today, I noticed strange situation:<br /><br /> The same query run on different servers has very different
plan:<br/><br /> Q: SELECT b.* FROM kredytob b  WHERE pesel = '22222222222'  ORDER BY b.id DESC LIMIT 1 <br /><br />
Slowplan:<br /><br /> "Limit  (cost=0.43..28712.33 rows=1 width=4) (actual time=2574.041..2574.044 rows=1 loops=1)"<br
/>"  Output: id"<br /> "  Buffers: shared hit=316132 read=110001"<br /> "  ->  Index Scan Backward using
kredytob_pkeyon public.kredytob b  (cost=0.43..3244444.80 rows=113 width=4) (actual time=2574.034..2574.034 rows=1
loops=1)"<br/> "        Output: id"<br /> "        Filter: (b.pesel = '22222222222'::bpchar)"<br /> "        Rows
Removedby Filter: 433609"<br /> "        Buffers: shared hit=316132 read=110001"<br /> "Planning time: 0.414 ms"<br />
"Executiontime: 2574.139 ms"<br /><br /><br /> Fast plan:<br /> "Limit  (cost=115240.66..115240.66 rows=1 width=4)
(actualtime=463.275..463.276 rows=1 loops=1)"<br /> "  Output: id"<br /> "  Buffers: shared hit=14661 read=4576"<br />
" ->  Sort  (cost=115240.66..115240.94 rows=112 width=4) (actual time=463.271..463.271 rows=1 loops=1)"<br />
"       Output: id"<br /> "        Sort Key: b.id DESC"<br /> "        Sort Method: top-N heapsort  Memory: 25kB"<br />
"       Buffers: shared hit=14661 read=4576"<br /> "        ->  Index Scan using kredytob_pesel_typkred_opclass_idx
onpublic.kredytob b  (cost=0.43..115240.10 rows=112 width=4) (actual time=311.347..463.183 rows=5 loops=1)"<br />
"             Output: id"<br /> "              Index Cond: (b.pesel = '22222222222'::bpchar)"<br /> "             
Buffers:shared hit=14661 read=4576"<br /> "Planning time: 0.383 ms"<br /> "Execution time: 463.324 ms"<br /><br /> Data
isalmost equal - "slow" has a few more rows in table. ("Fast" is a copy from 1 am today).<br /> Why runtime is
slower?<br/><br /> -- <br /> Andrzej Zawadzki<br /> 

<div class="moz-cite-prefix">On 10.10.2016 19:09, Pavel Stehule wrote:<br /></div><blockquote
cite="mid:CAFj8pRCFZGWtu5NuJ7pcVmXECTiC5wHfYJ7VjhgObcEz+AAzxw@mail.gmail.com"type="cite"><div dir="ltr"><br /><div
class="gmail_extra"><br/><div class="gmail_quote">2016-10-10 17:31 GMT+02:00 Andrzej Zawadzki <span dir="ltr"><<a
href="mailto:zawadaa@wp.pl"moz-do-not-send="true" target="_blank">zawadaa@wp.pl</a>></span>:<br /><blockquote
class="gmail_quote"style="margin:0px 0px 0px             0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex"><divbgcolor="#FFFFFF"> Hi,<br /> Today, I noticed strange situation:<br /><br /> The
samequery run on different servers has very different plan:<br /><br /> Q: SELECT b.* FROM kredytob b  WHERE pesel =
'22222222222' ORDER BY <a href="http://b.id" moz-do-not-send="true" target="_blank">b.id</a> DESC LIMIT 1 <br /><br />
Slowplan:<br /><br /> "Limit  (cost=0.43..28712.33 rows=1 width=4) (actual time=2574.041..2574.044 rows=1 loops=1)"<br
/>"  Output: id"<br /> "  Buffers: shared hit=316132 read=110001"<br /> "  ->  Index Scan Backward using
kredytob_pkeyon public.kredytob b  (cost=0.43..3244444.80 rows=113 width=4) (actual time=2574.034..2574.034 rows=1
loops=1)"<br/> "        Output: id"<br /> "        Filter: (b.pesel = '22222222222'::bpchar)"<br /> "        Rows
Removedby Filter: 433609"<br /></div></blockquote><div><br /></div><div>here is backward index scan with - lot of rows
isthrown <br /><br /> Rows Removed by Filter: 433609" <br /><br /></div><div>probably index definition on these servers
aredifferent<br /></div></div></div></div></blockquote><br /> No! That's binary copy of whole database.<br /> Index are
thesame!<br /> But, when I ask database without "ORDER..."<br /> (SELECT b.id FROM kredytob b  WHERE pesel =
'22222222222';)<br/>  then:<br /><br /> "SLOW"<br /><br /> "Index Scan using kredytob_pesel_typkred_opclass_idx on
public.kredytobb  (cost=0.43..115349.30 rows=113 width=4) (actual time=233.767..392.710 rows=5 loops=1)"<br /> " 
Output:id"<br /> "  Index Cond: (b.pesel = '22222222222'::bpchar)"<br /> "  Buffers: shared hit=19259"<br /> "Planning
time:0.254 ms"<br /> "Execution time: 392.761 ms"<br /><br /> "FAST"<br /><br /> "Index Scan using
kredytob_pesel_typkred_opclass_idxon public.kredytob b  (cost=0.43..115240.10 rows=112 width=4) (actual
time=378.737..836.208rows=5 loops=1)"<br /> "  Output: id"<br /> "  Index Cond: (b.pesel = '22222222222'::bpchar)"<br
/>"  Buffers: shared read=19237"<br /> "Planning time: 0.568 ms"<br /> "Execution time: 836.261 ms"<br /><br /> So,
indexis used in both queries but when is "ORDER" then everything change...<br /> Why?<br /><br /><br /><blockquote
cite="mid:CAFj8pRCFZGWtu5NuJ7pcVmXECTiC5wHfYJ7VjhgObcEz+AAzxw@mail.gmail.com"type="cite"><div dir="ltr"><div
class="gmail_extra"><divclass="gmail_quote"><div><br /></div><div>regards<br /><br /></div><div>Pavel<br
/></div><div><br/></div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px
0.8ex;border-left:1pxsolid             rgb(204,204,204);padding-left:1ex"><div bgcolor="#FFFFFF"> "        Buffers:
sharedhit=316132 read=110001"<br /> "Planning time: 0.414 ms"<br /> "Execution time: 2574.139 ms"<br /><br /><br />
Fastplan:<br /> "Limit  (cost=115240.66..115240.66 rows=1 width=4) (actual time=463.275..463.276 rows=1 loops=1)"<br />
" Output: id"<br /> "  Buffers: shared hit=14661 read=4576"<br /> "  ->  Sort  (cost=115240.66..115240.94 rows=112
width=4)(actual time=463.271..463.271 rows=1 loops=1)"<br /> "        Output: id"<br /> "        Sort Key: <a
href="http://b.id"moz-do-not-send="true" target="_blank">b.id</a> DESC"<br /> "        Sort Method: top-N heapsort 
Memory:25kB"<br /> "        Buffers: shared hit=14661 read=4576"<br /> "        ->  Index Scan using
kredytob_pesel_typkred_<wbr/>opclass_idx on public.kredytob b  (cost=0.43..115240.10 rows=112 width=4) (actual
time=311.347..463.183rows=5 loops=1)"<br /> "              Output: id"<br /> "              Index Cond: (b.pesel =
'22222222222'::bpchar)"<br/> "              Buffers: shared hit=14661 read=4576"<br /> "Planning time: 0.383 ms"<br />
"Executiontime: 463.324 ms"<br /><br /> Data is almost equal - "slow" has a few more rows in table. ("Fast" is a copy
from1 am today).<br /> Why runtime is slower?<span class="gmail-HOEnZb"><font color="#888888"><br /><br /> -- <br />
AndrzejZawadzki<br /></font></span></div></blockquote></div><br /></div></div></blockquote><p><br /> 

<div class="moz-cite-prefix">On 10.10.2016 17:31, Andrzej Zawadzki wrote:<br /></div><blockquote
cite="mid:bb1d234e-62ee-70e8-44ef-9b0919ec1268@wp.pl"type="cite"> Hi,<br /> Today, I noticed strange situation:<br
/><br/> The same query run on different servers has very different plan:<br /><br /> Q: SELECT b.* FROM kredytob b 
WHEREpesel = '22222222222'  ORDER BY b.id DESC LIMIT 1 <br /><br /> Slow plan:<br /><br /> "Limit  (cost=0.43..28712.33
rows=1width=4) (actual time=2574.041..2574.044 rows=1 loops=1)"<br /> "  Output: id"<br /> "  Buffers: shared
hit=316132read=110001"<br /> "  ->  Index Scan Backward using kredytob_pkey on public.kredytob b 
(cost=0.43..3244444.80rows=113 width=4) (actual time=2574.034..2574.034 rows=1 loops=1)"<br /> "        Output: id"<br
/>"        Filter: (b.pesel = '22222222222'::bpchar)"<br /> "        Rows Removed by Filter: 433609"<br /> "       
Buffers:shared hit=316132 read=110001"<br /> "Planning time: 0.414 ms"<br /> "Execution time: 2574.139 ms"<br /><br
/><br/> Fast plan:<br /> "Limit  (cost=115240.66..115240.66 rows=1 width=4) (actual time=463.275..463.276 rows=1
loops=1)"<br/> "  Output: id"<br /> "  Buffers: shared hit=14661 read=4576"<br /> "  ->  Sort 
(cost=115240.66..115240.94rows=112 width=4) (actual time=463.271..463.271 rows=1 loops=1)"<br /> "        Output:
id"<br/> "        Sort Key: b.id DESC"<br /> "        Sort Method: top-N heapsort  Memory: 25kB"<br /> "       
Buffers:shared hit=14661 read=4576"<br /> "        ->  Index Scan using kredytob_pesel_typkred_opclass_idx on
public.kredytobb  (cost=0.43..115240.10 rows=112 width=4) (actual time=311.347..463.183 rows=5 loops=1)"<br />
"             Output: id"<br /> "              Index Cond: (b.pesel = '22222222222'::bpchar)"<br /> "             
Buffers:shared hit=14661 read=4576"<br /> "Planning time: 0.383 ms"<br /> "Execution time: 463.324 ms"<br /><br /> Data
isalmost equal - "slow" has a few more rows in table. ("Fast" is a copy from 1 am today).<br /> Why runtime is
slower?<br/></blockquote><br /> I made another INDEX, without opclass:<br /><br /> CREATE INDEX
kredytob_pesel_typkred_idx<br/>   ON public.kredytob<br />   USING btree<br />   (pesel COLLATE pg_catalog."default",
typkred);<br/><br /> after that: analyze kredytob;<br /><br /> And now:<br /> "Limit  (cost=333.31..333.31 rows=1
width=4)(actual time=0.100..0.102 rows=1 loops=1)"<br /> "  Output: id"<br /> "  Buffers: shared hit=8"<br /> "  -> 
Sort (cost=333.31..333.59 rows=114 width=4) (actual time=0.095..0.095 rows=1 loops=1)"<br /> "        Output: id"<br />
"       Sort Key: b.id DESC"<br /> "        Sort Method: top-N heapsort  Memory: 25kB"<br /> "        Buffers: shared
hit=8"<br/> "        ->  Index Scan using kredytob_pesel_typkred_idx on public.kredytob b  (cost=0.43..332.74
rows=114width=4) (actual time=0.046..0.065 rows=5 loops=1)"<br /> "              Output: id"<br /> "              Index
Cond:(b.pesel = '22222222222'::bpchar)"<br /> "              Buffers: shared hit=8"<br /> "Planning time: 0.438 ms"<br
/>"Execution time: 0.154 ms"<br /><br /> So, what is a reason that "SLOW" server doesn't like opclass index?<br /><br
/>-- <br /> Andrzej<br /> 

<div class="moz-cite-prefix">On 11.10.2016 03:47, Pavel Stehule wrote:<br /></div><blockquote
cite="mid:CAFj8pRBKLGJkyNdBdhg0CfwD+ZMTrC0xmqJBH64kBEJEYLHxJg@mail.gmail.com"type="cite"><div dir="ltr"><br /><div
class="gmail_extra"><br/><div class="gmail_quote">2016-10-10 23:17 GMT+02:00 Andrzej Zawadzki <span dir="ltr"><<a
href="mailto:zawadaa@gmail.com"moz-do-not-send="true" target="_blank">zawadaa@gmail.com</a>></span>:<br
/><blockquoteclass="gmail_quote" style="margin:0 0 0             .8ex;border-left:1px #ccc solid;padding-left:1ex"><div
bgcolor="#FFFFFF"text="#000000"><div><div class="h5"><div class="m_-861737590477819645moz-cite-prefix">On 10.10.2016
17:31,Andrzej Zawadzki wrote:<br /></div><blockquote type="cite"> Hi,<br /> Today, I noticed strange situation:<br
/><br/> The same query run on different servers has very different plan:<br /><br /> Q: SELECT b.* FROM kredytob b 
WHEREpesel = '22222222222'  ORDER BY <a href="http://b.id" moz-do-not-send="true" target="_blank">b.id</a> DESC LIMIT 1
<br/><br /> Slow plan:<br /><br /> "Limit  (cost=0.43..28712.33 rows=1 width=4) (actual time=2574.041..2574.044 rows=1
loops=1)"<br/> "  Output: id"<br /> "  Buffers: shared hit=316132 read=110001"<br /> "  ->  Index Scan Backward
usingkredytob_pkey on public.kredytob b  (cost=0.43..3244444.80 rows=113 width=4) (actual time=2574.034..2574.034
rows=1loops=1)"<br /> "        Output: id"<br /> "        Filter: (b.pesel = '22222222222'::bpchar)"<br /> "       
RowsRemoved by Filter: 433609"<br /> "        Buffers: shared hit=316132 read=110001"<br /> "Planning time: 0.414
ms"<br/> "Execution time: 2574.139 ms"<br /><br /><br /> Fast plan:<br /> "Limit  (cost=115240.66..115240.66 rows=1
width=4)(actual time=463.275..463.276 rows=1 loops=1)"<br /> "  Output: id"<br /> "  Buffers: shared hit=14661
read=4576"<br/> "  ->  Sort  (cost=115240.66..115240.94 rows=112 width=4) (actual time=463.271..463.271 rows=1
loops=1)"<br/> "        Output: id"<br /> "        Sort Key: <a href="http://b.id" moz-do-not-send="true"
target="_blank">b.id</a>DESC"<br /> "        Sort Method: top-N heapsort  Memory: 25kB"<br /> "        Buffers: shared
hit=14661read=4576"<br /> "        ->  Index Scan using kredytob_pesel_typkred_<wbr />opclass_idx on public.kredytob
b (cost=0.43..115240.10 rows=112 width=4) (actual time=311.347..463.183 rows=5 loops=1)"<br /> "              Output:
id"<br/> "              Index Cond: (b.pesel = '22222222222'::bpchar)"<br /> "              Buffers: shared hit=14661
read=4576"<br/> "Planning time: 0.383 ms"<br /> "Execution time: 463.324 ms"<br /><br /> Data is almost equal - "slow"
hasa few more rows in table. ("Fast" is a copy from 1 am today).<br /> Why runtime is slower?<br /></blockquote><br
/></div></div>I made another INDEX, without opclass:<br /><br /> CREATE INDEX kredytob_pesel_typkred_idx<br />   ON
public.kredytob<br/>   USING btree<br />   (pesel COLLATE pg_catalog."default", typkred);<br /><br /> after that:
analyzekredytob;<br /><br /> And now:<br /> "Limit  (cost=333.31..333.31 rows=1 width=4) (actual time=0.100..0.102
rows=1loops=1)"<br /> "  Output: id"<br /> "  Buffers: shared hit=8"<br /> "  ->  Sort  (cost=333.31..333.59
rows=114width=4) (actual time=0.095..0.095 rows=1 loops=1)"<span class=""><br /> "        Output: id"<br /> "       
SortKey: <a href="http://b.id" moz-do-not-send="true" target="_blank">b.id</a> DESC"<br /> "        Sort Method: top-N
heapsort Memory: 25kB"<br /></span> "        Buffers: shared hit=8"<br /> "        ->  Index Scan using
kredytob_pesel_typkred_idxon public.kredytob b  (cost=0.43..332.74 rows=114 width=4) (actual time=0.046..0.065 rows=5
loops=1)"<spanclass=""><br /> "              Output: id"<br /> "              Index Cond: (b.pesel =
'22222222222'::bpchar)"<br/></span> "              Buffers: shared hit=8"<br /> "Planning time: 0.438 ms"<br />
"Executiontime: 0.154 ms"<br /><br /> So, what is a reason that "SLOW" server doesn't like opclass index?<span
class="HOEnZb"><fontcolor="#888888"><br /></font></span></div></blockquote><div><br /></div><div>what is default
locales?<br/><br /></div></div></div></div></blockquote> LATIN2 - that's why I use opclass.<br /><br /> -- <br />
Andrzej<br/>