Обсуждение: 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 /> 

2016-10-10 17:31 GMT+02:00 Andrzej Zawadzki <zawadaa@wp.pl>:

Hi,
Today, I noticed strange situation:

The same query run on different servers has very different plan:

Q: SELECT b.* FROM kredytob b  WHERE pesel = '22222222222'  ORDER BY b.id DESC LIMIT 1

Slow plan:

"Limit  (cost=0.43..28712.33 rows=1 width=4) (actual time=2574.041..2574.044 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=316132 read=110001"
"  ->  Index Scan Backward using kredytob_pkey on public.kredytob b  (cost=0.43..3244444.80 rows=113 width=4) (actual time=2574.034..2574.034 rows=1 loops=1)"
"        Output: id"
"        Filter: (b.pesel = '22222222222'::bpchar)"
"        Rows Removed by Filter: 433609"

here is backward index scan with - lot of rows is thrown

Rows Removed by Filter: 433609"

probably index definition on these servers are different

regards

Pavel

 

"        Buffers: shared hit=316132 read=110001"
"Planning time: 0.414 ms"
"Execution time: 2574.139 ms"


Fast plan:
"Limit  (cost=115240.66..115240.66 rows=1 width=4) (actual time=463.275..463.276 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=14661 read=4576"
"  ->  Sort  (cost=115240.66..115240.94 rows=112 width=4) (actual time=463.271..463.271 rows=1 loops=1)"
"        Output: id"
"        Sort Key: b.id DESC"
"        Sort Method: top-N heapsort  Memory: 25kB"
"        Buffers: shared hit=14661 read=4576"
"        ->  Index Scan using kredytob_pesel_typkred_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)"
"              Output: id"
"              Index Cond: (b.pesel = '22222222222'::bpchar)"
"              Buffers: shared hit=14661 read=4576"
"Planning time: 0.383 ms"
"Execution time: 463.324 ms"

Data is almost equal - "slow" has a few more rows in table. ("Fast" is a copy from 1 am today).
Why runtime is slower?

--
Andrzej Zawadzki

Hi,
Today, I noticed strange situation:

The same query run on different servers has very different plan:

Q: SELECT b.* FROM kredytob b  WHERE pesel = '22222222222'  ORDER BY b.id DESC LIMIT 1

Slow plan:

"Limit  (cost=0.43..28712.33 rows=1 width=4) (actual time=2574.041..2574.044 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=316132 read=110001"
"  ->  Index Scan Backward using kredytob_pkey on public.kredytob b  (cost=0.43..3244444.80 rows=113 width=4) (actual time=2574.034..2574.034 rows=1 loops=1)"
"        Output: id"
"        Filter: (b.pesel = '22222222222'::bpchar)"
"        Rows Removed by Filter: 433609"
"        Buffers: shared hit=316132 read=110001"
"Planning time: 0.414 ms"
"Execution time: 2574.139 ms"


Fast plan:
"Limit  (cost=115240.66..115240.66 rows=1 width=4) (actual time=463.275..463.276 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=14661 read=4576"
"  ->  Sort  (cost=115240.66..115240.94 rows=112 width=4) (actual time=463.271..463.271 rows=1 loops=1)"
"        Output: id"
"        Sort Key: b.id DESC"
"        Sort Method: top-N heapsort  Memory: 25kB"
"        Buffers: shared hit=14661 read=4576"
"        ->  Index Scan using kredytob_pesel_typkred_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)"
"              Output: id"
"              Index Cond: (b.pesel = '22222222222'::bpchar)"
"              Buffers: shared hit=14661 read=4576"
"Planning time: 0.383 ms"
"Execution time: 463.324 ms"

Data is almost equal - "slow" has a few more rows in table. ("Fast" is a copy from 1 am today).
Why runtime is slower?

2016-10-10 23:17 GMT+02:00 Andrzej Zawadzki <zawadaa@gmail.com>:

On 10.10.2016 17:31, Andrzej Zawadzki wrote:

Hi,
Today, I noticed strange situation:

The same query run on different servers has very different plan:

Q: SELECT b.* FROM kredytob b  WHERE pesel = '22222222222'  ORDER BY b.id DESC LIMIT 1

Slow plan:

"Limit  (cost=0.43..28712.33 rows=1 width=4) (actual time=2574.041..2574.044 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=316132 read=110001"
"  ->  Index Scan Backward using kredytob_pkey on public.kredytob b  (cost=0.43..3244444.80 rows=113 width=4) (actual time=2574.034..2574.034 rows=1 loops=1)"
"        Output: id"
"        Filter: (b.pesel = '22222222222'::bpchar)"
"        Rows Removed by Filter: 433609"
"        Buffers: shared hit=316132 read=110001"
"Planning time: 0.414 ms"
"Execution time: 2574.139 ms"


Fast plan:
"Limit  (cost=115240.66..115240.66 rows=1 width=4) (actual time=463.275..463.276 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=14661 read=4576"
"  ->  Sort  (cost=115240.66..115240.94 rows=112 width=4) (actual time=463.271..463.271 rows=1 loops=1)"
"        Output: id"
"        Sort Key: b.id DESC"
"        Sort Method: top-N heapsort  Memory: 25kB"
"        Buffers: shared hit=14661 read=4576"
"        ->  Index Scan using kredytob_pesel_typkred_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)"
"              Output: id"
"              Index Cond: (b.pesel = '22222222222'::bpchar)"
"              Buffers: shared hit=14661 read=4576"
"Planning time: 0.383 ms"
"Execution time: 463.324 ms"

Data is almost equal - "slow" has a few more rows in table. ("Fast" is a copy from 1 am today).
Why runtime is slower?

I made another INDEX, without opclass:

CREATE INDEX kredytob_pesel_typkred_idx
  ON public.kredytob
  USING btree
  (pesel COLLATE pg_catalog."default", typkred);

after that: analyze kredytob;

And now:
"Limit  (cost=333.31..333.31 rows=1 width=4) (actual time=0.100..0.102 rows=1 loops=1)"
"  Output: id"
"  Buffers: shared hit=8"
"  ->  Sort  (cost=333.31..333.59 rows=114 width=4) (actual time=0.095..0.095 rows=1 loops=1)"
"        Output: id"
"        Sort Key: b.id DESC"
"        Sort Method: top-N heapsort  Memory: 25kB"
"        Buffers: shared hit=8"
"        ->  Index Scan using kredytob_pesel_typkred_idx on public.kredytob b  (cost=0.43..332.74 rows=114 width=4) (actual time=0.046..0.065 rows=5 loops=1)"
"              Output: id"
"              Index Cond: (b.pesel = '22222222222'::bpchar)"
"              Buffers: shared hit=8"
"Planning time: 0.438 ms"
"Execution time: 0.154 ms"

So, what is a reason that "SLOW" server doesn't like opclass index?

what is default locales?