Re: Slow execution time when querying view with WHERE clause

Tom Lane wrote:
> Mike Mascari <mascarm(at)mascari(dot)com> writes:
>
>>When I query the view with a simple filter, I get:
>
>
>>explain analyze select * from p_areas where deactive is null;
>
>
> The problem seems to be here:
>
>
>> -> Seq Scan on _areas a (cost=0.00..2.48 rows=1 width=163) (actual time=0.037..0.804 rows=48 loops=1)
>> Filter: (deactive IS NULL)
>
>
> Why is it so completely off about the selectivity of the IS NULL clause?
> Are you sure you ANALYZEd this table recently?

Yes. I just did:

[estore(at)lexus] vacuum full analyze;
VACUUM
[estore(at)lexus] explain analyze select * from p_areas where deactive is null;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop IN Join (cost=8.62..512.47 rows=1 width=162) (actual time=1143.969..21811.417 rows=37 loops=1)
Join Filter: ("outer".area = "inner".area)
-> Seq Scan on _areas a (cost=0.00..2.49 rows=1 width=162) (actual time=0.037..1.673 rows=49 loops=1)
Filter: (deactive IS NULL)
-> Nested Loop (cost=8.62..25740.20 rows=2681 width=8) (actual time=1.172..429.501 rows=3566 loops=49)
-> Nested Loop (cost=8.62..16674.93 rows=2680 width=8) (actual time=1.125..281.570 rows=3566 loops=49)
-> Merge Join (cost=8.62..3012.72 rows=2778 width=8) (actual time=0.876..128.908 rows=3566 loops=49)
Merge Cond: ("outer".pricegroup = "inner".pricegroup)
-> Nested Loop IN Join (cost=8.62..1929.41 rows=9 width=8) (actual time=0.613..5.504 rows=9 loops=49)
Join Filter: ("outer".buyer = "inner".store)
-> Index Scan using i_pricemembers3 on _pricemembers p (cost=0.00..11.13 rows=217 width=16) (actual time=0.403..1.476 rows=142 loops=49)
-> Subquery Scan "IN_subquery" (cost=8.62..8.74 rows=8 width=8) (actual time=0.013..0.019 rows=1 loops=6950)
-> Unique (cost=8.62..8.66 rows=8 width=8) (actual time=0.007..0.010 rows=1 loops=6950)
-> Sort (cost=8.62..8.64 rows=8 width=8) (actual time=0.003..0.004 rows=1 loops=6950)
Sort Key: store
-> Append (cost=2.87..8.50 rows=8 width=8) (actual time=8.394..8.446 rows=1 loops=1)
-> Subquery Scan "*SELECT* 1" (cost=2.87..5.17 rows=5 width=8) (actual time=8.112..8.112 rows=0 loops=1)
-> Hash Join (cost=2.87..5.12 rows=5 width=8) (actual time=8.106..8.106 rows=0 loops=1)
Hash Cond: ("outer".company = "inner".company)
-> Seq Scan on _stores s (cost=0.00..2.13 rows=13 width=16) (actual time=0.014..0.052 rows=13 loops=1)
-> Hash (cost=2.87..2.87 rows=1 width=8) (actual time=7.878..7.878 rows=0 loops=1)
-> Seq Scan on _webusers w (cost=0.00..2.87 rows=1 width=8) (actual time=7.868..7.868 rows=0 loops=1)
Filter: (webuser = getwebuser())
-> Subquery Scan "*SELECT* 2" (cost=1.08..3.33 rows=3 width=8) (actual time=0.273..0.322 rows=1 loops=1)
-> Hash Join (cost=1.08..3.30 rows=3 width=8) (actual time=0.263..0.308 rows=1 loops=1)
Hash Cond: ("outer".company = "inner".company)
-> Seq Scan on _stores s (cost=0.00..2.13 rows=13 width=16) (actual time=0.008..0.042 rows=13 loops=1)
-> Hash (cost=1.07..1.07 rows=1 width=8) (actual time=0.093..0.093 rows=0 loops=1)
-> Seq Scan on _companies c (cost=0.00..1.07 rows=1 width=8) (actual time=0.061..0.081 rows=1 loops=1)
Filter: ((companyid)::text = 'DEFAULT'::text)
-> Index Scan using i_offers4 on _offers o (cost=0.00..1014.76 rows=16298 width=16) (actual time=0.244..72.742 rows=10433 loops=49)
-> Index Scan using i_inventories1 on _inventories i (cost=0.00..4.91 rows=1 width=16) (actual time=0.025..0.029 rows=1 loops=174715)
Index Cond: (i.inventory = "outer".inventory)
-> Index Scan using i_bins1 on _bins b (cost=0.00..3.37 rows=1 width=16) (actual time=0.022..0.027 rows=1 loops=174715)
Index Cond: (b.bin = "outer".bin)
Total runtime: 21813.209 ms

_areas looks like:

[estore(at)lexus] \d _areas
Table "temporal._areas"
Column | Type | Modifiers
--------------------+--------------------------+------------------------
area | bigint | not null
store | bigint | not null
name | character varying(32) | not null
description | character varying(64) | not null
email | character varying(48) | not null
phoneno | character varying(16) | not null
requisition_device | bigint | not null
inventory_device | bigint | not null
receive_device | bigint | not null
invoice_device | bigint | not null
activation_device | bigint | not null
active | timestamp with time zone | not null default now()
deactive | timestamp with time zone |
Indexes:
"i_areas1" unique, btree (area)
"i_areas2" unique, btree (store, name) WHERE (deactive IS NULL)
"i_areas3" btree (store, name)
Triggers:
t_areas1 BEFORE INSERT OR DELETE OR UPDATE ON _areas FOR EACH ROW EXECUTE PROCEDURE ri_areas()

Note that if I disable nestedloop plans, I get:

[estore(at)lexus] explain analyze select * from p_areas where deactive is null;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hash Join (cost=1456.90..1457.15 rows=1 width=162) (actual time=423.273..424.156 rows=37 loops=1)
Hash Cond: ("outer".area = "inner".area)
-> HashAggregate (cost=1454.40..1454.40 rows=48 width=8) (actual time=422.192..422.334 rows=37 loops=1)
-> Hash Join (cost=582.79..1447.70 rows=2681 width=8) (actual time=188.687..406.584 rows=5694 loops=1)
Hash Cond: ("outer".bin = "inner".bin)
-> Hash Join (cost=568.07..1386.07 rows=2680 width=8) (actual time=182.756..358.441 rows=5694 loops=1)
Hash Cond: ("outer".inventory = "inner".inventory)
-> Seq Scan on _inventories i (cost=0.00..280.04 rows=12004 width=16) (actual time=0.013..38.221 rows=12004 loops=1)
-> Hash (cost=561.12..561.12 rows=2778 width=8) (actual time=182.543..182.543 rows=0 loops=1)
-> Hash Join (cost=14.13..561.12 rows=2778 width=8) (actual time=9.854..160.963 rows=5694 loops=1)
Hash Cond: ("outer".pricegroup = "inner".pricegroup)
-> Seq Scan on _offers o (cost=0.00..396.98 rows=16298 width=16) (actual time=0.011..58.422 rows=16298 loops=1)
-> Hash (cost=14.10..14.10 rows=9 width=8) (actual time=9.728..9.728 rows=0 loops=1)
-> Hash IN Join (cost=8.76..14.10 rows=9 width=8) (actual time=8.616..9.657 rows=13 loops=1)
Hash Cond: ("outer".buyer = "inner".store)
-> Seq Scan on _pricemembers p (cost=0.00..4.17 rows=217 width=16) (actual time=0.011..0.565 rows=217 loops=1)
-> Hash (cost=8.74..8.74 rows=8 width=8) (actual time=8.465..8.465 rows=0 loops=1)
-> Subquery Scan "IN_subquery" (cost=8.62..8.74 rows=8 width=8) (actual time=8.446..8.455 rows=1 loops=1)
-> Unique (cost=8.62..8.66 rows=8 width=8) (actual time=8.430..8.435 rows=1 loops=1)
-> Sort (cost=8.62..8.64 rows=8 width=8) (actual time=8.424..8.426 rows=1 loops=1)
Sort Key: store
-> Append (cost=2.87..8.50 rows=8 width=8) (actual time=8.004..8.058 rows=1 loops=1)
-> Subquery Scan "*SELECT* 1" (cost=2.87..5.17 rows=5 width=8) (actual time=7.710..7.710 rows=0 loops=1)
-> Hash Join (cost=2.87..5.12 rows=5 width=8) (actual time=7.701..7.701 rows=0 loops=1)
Hash Cond: ("outer".company = "inner".company)
-> Seq Scan on _stores s (cost=0.00..2.13 rows=13 width=16) (actual time=0.013..0.052 rows=13 loops=1)
-> Hash (cost=2.87..2.87 rows=1 width=8) (actual time=7.486..7.486 rows=0 loops=1)
-> Seq Scan on _webusers w (cost=0.00..2.87 rows=1 width=8) (actual time=7.478..7.478 rows=0 loops=1)
Filter: (webuser = getwebuser())
-> Subquery Scan "*SELECT* 2" (cost=1.08..3.33 rows=3 width=8) (actual time=0.284..0.336 rows=1 loops=1)
-> Hash Join (cost=1.08..3.30 rows=3 width=8) (actual time=0.274..0.321 rows=1 loops=1)
Hash Cond: ("outer".company = "inner".company)
-> Seq Scan on _stores s (cost=0.00..2.13 rows=13 width=16) (actual time=0.008..0.046 rows=13 loops=1)
-> Hash (cost=1.07..1.07 rows=1 width=8) (actual time=0.096..0.096 rows=0 loops=1)
-> Seq Scan on _companies c (cost=0.00..1.07 rows=1 width=8) (actual time=0.064..0.083 rows=1 loops=1)
Filter: ((companyid)::text = 'DEFAULT'::text)
-> Hash (cost=13.18..13.18 rows=618 width=16) (actual time=5.849..5.849 rows=0 loops=1)
-> Seq Scan on _bins b (cost=0.00..13.18 rows=618 width=16) (actual time=0.027..3.554 rows=618 loops=1)
-> Hash (cost=2.49..2.49 rows=1 width=162) (actual time=0.960..0.960 rows=0 loops=1)
-> Seq Scan on _areas a (cost=0.00..2.49 rows=1 width=162) (actual time=0.033..0.197 rows=49 loops=1)
Filter: (deactive IS NULL)
Total runtime: 427.390 ms

Thanks!

Mike Mascari