Hello Everyone,
I'm struggling to get postgres to run a particular query quickly. It seems
that very early on, the planner seems to mis-estimate the number of rows
returned by a join which causes it to assume that there is only 1 row as it
goes up the tree. It then picks a nested loop join which seems to cause the
whole query to be slow. Or at least if I turn off nestloop, it runs in 216ms.
explain analyze SELECT 1
FROM
rpt_agencyquestioncache_171_0 par
right outer join namemaster dem on (par.nameid = dem.nameid and
dem.programid = 171)
right join activity_parentid_view ses on (par.activity = ses.activityid and
ses.programid=171)
left join (
select ct0.inter_agency_id,ct0.nameid
from rpt_agencyquestioncache_171_0 ct0
join rpt_agencyquestioncache_171_2 ct2 on ct2.participantid
=ct0.participantid
) as par30232 on (dem.nameid=par30232.nameid and
par30232.inter_agency_id=30232)
WHERE
( ( (par.provider_lfm) ='Child Guidance Treatment Centers Inc.'))
QUERY
PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=1990.12..5666.92 rows=1 width=0) (actual
time=82.185..91511.455 rows=1199 loops=1)
Join Filter: (dem.nameid = ct0.nameid)
-> Nested Loop Left Join (cost=45.92..1324.06 rows=1 width=4) (actual
time=0.973..74.206 rows=1199 loops=1)
-> Nested Loop (cost=45.92..1323.33 rows=1 width=8) (actual
time=0.964..61.264 rows=1199 loops=1)
-> Hash Join (cost=45.92..1251.07 rows=21 width=8) (actual
time=0.948..10.439 rows=1199 loops=1)
Hash Cond: (par.activity = a.activityid)
-> Bitmap Heap Scan on rpt_agencyquestioncache_171_0 par
(cost=21.92..1222.19 rows=1247 width=8) (actual time=0.415..3.081 rows=1199
loops=1)
Recheck Cond: (provider_lfm = 'Child Guidance
Treatment Centers Inc.'::text)
-> Bitmap Index Scan on rpt_aqc_45604_provider_lfm
(cost=0.00..21.61 rows=1247 width=0) (actual time=0.394..0.394 rows=1199
loops=1)
Index Cond: (provider_lfm = 'Child Guidance
Treatment Centers Inc.'::text)
-> Hash (cost=19.21..19.21 rows=383 width=4) (actual
time=0.513..0.513 rows=383 loops=1)
-> Index Scan using activity_programid_idx on
activity a (cost=0.00..19.21 rows=383 width=4) (actual time=0.034..0.307
rows=383 loops=1)
Index Cond: (programid = 171)
-> Index Scan using nameid_pk on namemaster dem
(cost=0.00..3.43 rows=1 width=4) (actual time=0.023..0.036 rows=1 loops=1199)
Index Cond: (par.nameid = dem.nameid)
Filter: (programid = 171)
-> Index Scan using activity_session_session_idx on activity_session
s (cost=0.00..0.72 rows=1 width=4) (actual time=0.007..0.007 rows=0 loops=1199)
Index Cond: (a.activityid = s."session")
-> Hash Join (cost=1944.20..4292.49 rows=4029 width=4) (actual
time=59.732..74.897 rows=4130 loops=1199)
Hash Cond: (ct2.participantid = ct0.participantid)
-> Seq Scan on rpt_agencyquestioncache_171_2 ct2 (cost=0.00..1747.00
rows=74800 width=4) (actual time=0.008..28.442 rows=74800 loops=1199)
-> Hash (cost=1893.84..1893.84 rows=4029 width=8) (actual
time=5.578..5.578 rows=4130 loops=1)
-> Bitmap Heap Scan on rpt_agencyquestioncache_171_0 ct0
(cost=55.48..1893.84 rows=4029 width=8) (actual time=0.625..3.714 rows=4130
loops=1)
Recheck Cond: (inter_agency_id = 30232)
-> Bitmap Index Scan on rpt_aqc_45604_inter_agency_id
(cost=0.00..54.47 rows=4029 width=0) (actual time=0.609..0.609 rows=4130
loops=1)
Index Cond: (inter_agency_id = 30232)
Total runtime: 91514.109 ms
(27 rows)
I've increased statistics to 100 of all pertinent columns in the query to no
effect.
I've vacuumed and all analyzed all tables in question. Autovac is on.
Settings of interest in postgresql.conf:
shared_buffers = 1024MB
work_mem = 256MB
maintenance_work_mem = 256MB
random_page_cost = 2.0
PG version: 8.2.4
Server Mem: 2G Ram
If I reduce random_page_cost to 1.0, I get the following query plan.
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=20.87..4377.13 rows=1 width=0) (actual
time=146.402..29585.011 rows=1199 loops=1)
-> Nested Loop Left Join (cost=20.87..4376.62 rows=1 width=4) (actual
time=146.287..29572.257 rows=1199 loops=1)
Join Filter: (dem.nameid = ct0.nameid)
-> Nested Loop (cost=20.87..857.70 rows=1 width=8) (actual
time=1.676..53.423 rows=1199 loops=1)
-> Hash Join (cost=20.87..818.60 rows=21 width=8) (actual
time=1.514..17.276 rows=1199 loops=1)
Hash Cond: (par.activity = a.activityid)
-> Index Scan using rpt_aqc_45604_provider_lfm on
rpt_agencyquestioncache_171_0 par (cost=0.00..792.85 rows=1247 width=8)
(actual time=0.293..9.976 rows=1199 loops=1)
Index Cond: (provider_lfm = 'Child Guidance
Treatment Centers Inc.'::text)
-> Hash (cost=16.08..16.08 rows=383 width=4) (actual
time=0.940..0.940 rows=383 loops=1)
-> Index Scan using activity_programid_idx on
activity a (cost=0.00..16.08 rows=383 width=4) (actual time=0.135..0.676
rows=383 loops=1)
Index Cond: (programid = 171)
-> Index Scan using nameid_pk on namemaster dem
(cost=0.00..1.85 rows=1 width=4) (actual time=0.024..0.026 rows=1 loops=1199)
Index Cond: (par.nameid = dem.nameid)
Filter: (programid = 171)
-> Nested Loop (cost=0.00..3468.56 rows=4029 width=4) (actual
time=0.087..23.199 rows=4130 loops=1199)
-> Index Scan using rpt_aqc_45604_inter_agency_id on
rpt_agencyquestioncache_171_0 ct0 (cost=0.00..1126.10 rows=4029 width=8)
(actual time=0.019..2.517 rows=4130 loops=1199)
Index Cond: (inter_agency_id = 30232)
-> Index Scan using rpt_aqc_45606_participantid on
rpt_agencyquestioncache_171_2 ct2 (cost=0.00..0.57 rows=1 width=4) (actual
time=0.003..0.003 rows=1 loops=4951870)
Index Cond: (ct2.participantid = ct0.participantid)
-> Index Scan using activity_session_session_idx on activity_session s
(cost=0.00..0.49 rows=1 width=4) (actual time=0.007..0.007 rows=0 loops=1199)
Index Cond: (a.activityid = s."session")
Total runtime: 29587.932 ms
(22 rows)
With nestloop off I get the following query plan:
set enable_nestloop=false;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hash Left Join (cost=6393.91..7603.11 rows=1 width=0) (actual
time=210.324..215.785 rows=1199 loops=1)
Hash Cond: (a.activityid = s."session")
-> Hash Left Join (cost=6130.14..7339.01 rows=1 width=4) (actual
time=175.072..179.623 rows=1199 loops=1)
Hash Cond: (dem.nameid = ct0.nameid)
-> Hash Join (cost=1787.29..2992.69 rows=1 width=8) (actual
time=92.812..96.361 rows=1199 loops=1)
Hash Cond: (par.nameid = dem.nameid)
-> Hash Join (cost=45.92..1251.07 rows=21 width=8) (actual
time=1.046..3.148 rows=1199 loops=1)
Hash Cond: (par.activity = a.activityid)
-> Bitmap Heap Scan on rpt_agencyquestioncache_171_0 par
(cost=21.92..1222.19 rows=1247 width=8) (actual time=0.453..1.126 rows=1199
loops=1)
Recheck Cond: (provider_lfm = 'Child Guidance
Treatment Centers Inc.'::text)
-> Bitmap Index Scan on rpt_aqc_45604_provider_lfm
(cost=0.00..21.61 rows=1247 width=0) (actual time=0.433..0.433 rows=1199
loops=1)
Index Cond: (provider_lfm = 'Child Guidance
Treatment Centers Inc.'::text)
-> Hash (cost=19.21..19.21 rows=383 width=4) (actual
time=0.566..0.566 rows=383 loops=1)
-> Index Scan using activity_programid_idx on
activity a (cost=0.00..19.21 rows=383 width=4) (actual time=0.035..0.303
rows=383 loops=1)
Index Cond: (programid = 171)
-> Hash (cost=1551.74..1551.74 rows=15170 width=4) (actual
time=91.725..91.725 rows=15575 loops=1)
-> Index Scan using namemaster_programid_idx on
namemaster dem (cost=0.00..1551.74 rows=15170 width=4) (actual
time=0.197..81.753 rows=15575 loops=1)
Index Cond: (programid = 171)
-> Hash (cost=4292.49..4292.49 rows=4029 width=4) (actual
time=82.217..82.217 rows=4130 loops=1)
-> Hash Join (cost=1944.20..4292.49 rows=4029 width=4) (actual
time=65.129..79.879 rows=4130 loops=1)
Hash Cond: (ct2.participantid = ct0.participantid)
-> Seq Scan on rpt_agencyquestioncache_171_2 ct2
(cost=0.00..1747.00 rows=74800 width=4) (actual time=0.014..28.093 rows=74800
loops=1)
-> Hash (cost=1893.84..1893.84 rows=4029 width=8)
(actual time=6.238..6.238 rows=4130 loops=1)
-> Bitmap Heap Scan on
rpt_agencyquestioncache_171_0 ct0 (cost=55.48..1893.84 rows=4029 width=8)
(actual time=0.726..3.652 rows=4130 loops=1)
Recheck Cond: (inter_agency_id = 30232)
-> Bitmap Index Scan on
rpt_aqc_45604_inter_agency_id (cost=0.00..54.47 rows=4029 width=0) (actual
time=0.702..0.702 rows=4130 loops=1)
Index Cond: (inter_agency_id = 30232)
-> Hash (cost=150.01..150.01 rows=9101 width=4) (actual
time=35.206..35.206 rows=9101 loops=1)
-> Seq Scan on activity_session s (cost=0.00..150.01 rows=9101
width=4) (actual time=9.201..29.911 rows=9101 loops=1)
Total runtime: 216.649 ms
---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to [EMAIL PROTECTED] so that your
message can get through to the mailing list cleanly
