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 majordomo@xxxxxxxxxxxxxx so that your
message can get through to the mailing list cleanly
