Skip site navigation (1) Skip section navigation (2)

Function scan/Index scan to nested loop

From: "Carlo Stonebanks" <stonec(dot)register(at)sympatico(dot)ca>
To: pgsql-performance(at)postgresql(dot)org
Subject: Function scan/Index scan to nested loop
Date: 2010-05-11 05:32:28
Message-ID: hsaq4t$c3s$1@news.hub.org (view raw or flat)
Thread:
Lists: pgsql-performance
Hello all,

A query ran twice in succession performs VERY poorly the first time as it 
iterates through the nested loop. The second time, it rips. Please see SQL, 
SLOW PLAN and FAST PLAN below.

I don't know why these nested loops are taking so long to execute.
"  ->  Nested Loop  (cost=0.00..42866.98 rows=77 width=18) (actual 
time=126.354..26301.027 rows=9613 loops=1)"
"        ->  Nested Loop  (cost=0.00..42150.37 rows=122 width=18) (actual 
time=117.369..15349.533 rows=13247 loops=1)"

The loop members appear to be finished quickly. I suspect that the results 
for the function aren't really as fast as reported, and are actually taking 
much longer to comeplete returning results.
"              ->  Function Scan on zips_in_mile_range  (cost=0.00..52.50 
rows=67 width=40) (actual time=104.196..104.417 rows=155 loops=1)"
"                    Filter: (zip > ''::text)"

Is this possible? I can't see what other delay there could be.

The second time the query runs, the loops are fast:
"  ->  Nested Loop  (cost=0.00..42866.98 rows=77 width=18) (actual 
time=97.073..266.826 rows=9613 loops=1)"
"        ->  Nested Loop  (cost=0.00..42150.37 rows=122 width=18) (actual 
time=97.058..150.172 rows=13247 loops=1)"

Since it is fast the second time, I wonder if this is related at all to the 
function being IMMUTABLE? (Even though it's IMMUTABLE it reads a very static 
table)

This DB is a copy of another DB, on the same server host, same drive but 
different tablespace. The original query has good performance, and is hit 
often by the live web server. With the copy - which performs poorly - the 
query is hit infrequently.

Is there any evidence for why the nested loop is slow?

Code and plans follow - regards and thanks!

Carlo

SQL:
select
      pp.provider_practice_id,
      p.provider_id,
      distance,
      pp.is_principal,
      p.provider_id as sort_order
   from mdx_core.provider as p
   join mdx_core.provider_practice as pp
   on pp.provider_id = p.provider_id
   join (select * from mdx_core.zips_in_mile_range('75203', 15::numeric)
where zip > '') as nearby
   on nearby.zip = substr(pp.default_postal_code, 1, 5)
   where
      pp.default_country_code = 'US'
      and p.provider_status_code = 'A' and p.is_visible = 'Y'
      and pp.is_principal = 'Y'
      and coalesce(pp.record_status, 'A') = 'A'
   order by sort_order, distance

SLOW PLAN:
"Sort  (cost=42869.40..42869.59 rows=77 width=18) (actual 
time=26316.495..26322.102 rows=9613 loops=1)"
"  Sort Key: p.provider_id, zips_in_mile_range.distance"
"  Sort Method:  quicksort  Memory: 1136kB"
"  ->  Nested Loop  (cost=0.00..42866.98 rows=77 width=18) (actual 
time=126.354..26301.027 rows=9613 loops=1)"
"        ->  Nested Loop  (cost=0.00..42150.37 rows=122 width=18) (actual 
time=117.369..15349.533 rows=13247 loops=1)"
"              ->  Function Scan on zips_in_mile_range  (cost=0.00..52.50 
rows=67 width=40) (actual time=104.196..104.417 rows=155 loops=1)"
"                    Filter: (zip > ''::text)"
"              ->  Index Scan using 
provider_practice_default_base_zip_country_idx on provider_practice pp 
(cost=0.00..628.30 rows=2 width=19) (actual time=1.205..98.231 rows=85 
loops=155)"
"                    Index Cond: ((pp.default_country_code = 'US'::bpchar) 
AND (substr((pp.default_postal_code)::text, 1, 5) = zips_in_mile_range.zip) 
AND (pp.is_principal = 'Y'::bpchar))"
"                    Filter: (COALESCE(pp.record_status, 'A'::bpchar) = 
'A'::bpchar)"
"        ->  Index Scan using provider_provider_id_provider_status_code_idx 
on provider p  (cost=0.00..5.86 rows=1 width=4) (actual time=0.823..0.824 
rows=1 loops=13247)"
"              Index Cond: ((p.provider_id = pp.provider_id) AND 
(p.provider_status_code = 'A'::bpchar))"
"              Filter: (p.is_visible = 'Y'::bpchar)"
"Total runtime: 26327.329 ms"

FAST PLAN:
"Sort  (cost=42869.40..42869.59 rows=77 width=18) (actual 
time=278.722..284.326 rows=9613 loops=1)"
"  Sort Key: p.provider_id, zips_in_mile_range.distance"
"  Sort Method:  quicksort  Memory: 1136kB"
"  ->  Nested Loop  (cost=0.00..42866.98 rows=77 width=18) (actual 
time=97.073..266.826 rows=9613 loops=1)"
"        ->  Nested Loop  (cost=0.00..42150.37 rows=122 width=18) (actual 
time=97.058..150.172 rows=13247 loops=1)"
"              ->  Function Scan on zips_in_mile_range  (cost=0.00..52.50 
rows=67 width=40) (actual time=97.013..97.161 rows=155 loops=1)"
"                    Filter: (zip > ''::text)"
"              ->  Index Scan using 
provider_practice_default_base_zip_country_idx on provider_practice pp 
(cost=0.00..628.30 rows=2 width=19) (actual time=0.017..0.236 rows=85 
loops=155)"
"                    Index Cond: ((pp.default_country_code = 'US'::bpchar) 
AND (substr((pp.default_postal_code)::text, 1, 5) = zips_in_mile_range.zip) 
AND (pp.is_principal = 'Y'::bpchar))"
"                    Filter: (COALESCE(pp.record_status, 'A'::bpchar) = 
'A'::bpchar)"
"        ->  Index Scan using provider_provider_id_provider_status_code_idx 
on provider p  (cost=0.00..5.86 rows=1 width=4) (actual time=0.006..0.007 
rows=1 loops=13247)"
"              Index Cond: ((p.provider_id = pp.provider_id) AND 
(p.provider_status_code = 'A'::bpchar))"
"              Filter: (p.is_visible = 'Y'::bpchar)"
"Total runtime: 289.582 ms"


Responses

pgsql-performance by date

Next:From: Scott MarloweDate: 2010-05-11 07:07:26
Subject: Re: Function scan/Index scan to nested loop
Previous:From: Josh BerkusDate: 2010-05-10 21:16:46
Subject: Re: 8K recordsize bad on ZFS?

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group