[PERFORM] Why query plan is different?

[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 = '222'  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..324.80 rows=113 width=4) (actual
time=2574.034..2574.034 rows=1 loops=1)"
"    Output: id"
"    Filter: (b.pesel = '222'::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 = '222'::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
  

Re: [PERFORM] Why query plan is different?

[Pavel Stehule]

2016-10-10 17:31 GMT+02:00 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 = '222'  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..324.80 rows=113 width=4) (actual time=2574.034..2574.034
> rows=1 loops=1)"
> "Output: id"
> "Filter: (b.pesel = '222'::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 = '222'::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
>

Re: [PERFORM] Why query plan is different?

[Andrzej Zawadzki]

  
  
On 10.10.2016 19:09, Pavel Stehule
  wrote:


  

  2016-10-10 17:31 GMT+02:00 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 =
'222'  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..324.80 rows=113
width=4) (actual time=2574.034..2574.034 rows=1
loops=1)"
"    Output: id"
"    Filter: (b.pesel = '222'::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

  

  


No! That's binary copy of whole database.
Index are the same!
But, when I ask database without "ORDER..."
(SELECT b.id FROM kredytob b  WHERE pesel = '222';)
 then:

"SLOW"

"Index Scan using kredytob_pesel_typkred_opclass_idx on
public.kredytob b  (cost=0.43..115349.30 rows=113 width=4) (actual
time=233.767..392.710 rows=5 loops=1)"
"  Output: id"
"  Index Cond: (b.pesel = '222'::bpchar)"
"  Buffers: shared hit=19259"
"Planning time: 0.254 ms"
"Execution time: 392.761 ms"

"FAST"

"Index Scan using kredytob_pesel_typkred_opclass_idx on
public.kredytob b  (cost=0.43..115240.10 rows=112 width=4) (actual
time=378.737..836.208 rows=5 loops=1)"
"  Output: id"
"  Index Cond: (b.pesel = '222'::bpchar)"
"  Buffers: shared read=19237"
"Planning time: 0.568 ms"
"Execution time: 836.261 ms"

So, index is used in both queries but when is "ORDER" then
everything change...
Why?



  

  


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 =
'222'::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
  

  
  

  



  

Re: [PERFORM] Why query plan is different?

[Andrzej Zawadzki]

  
  
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 = '222'  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..324.80 rows=113 width=4)
  (actual time=2574.034..2574.034 rows=1 loops=1)"
  "    Output: id"
  "    Filter: (b.pesel = '222'::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 = '222'::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 = '222'::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?

-- 
Andrzej
  

Re: [PERFORM] Why query plan is different?

[Pavel Stehule]

2016-10-10 23:17 GMT+02:00 Andrzej Zawadzki :

> 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 = '222'  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..324.80 rows=113 width=4) (actual time=2574.034..2574.034
> rows=1 loops=1)"
> "Output: id"
> "Filter: (b.pesel = '222'::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 = '222'::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 = '222'::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?

Pavel


>
> --
> Andrzej
>