Thread: Incorrect estimates on columns
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-estimatethe 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)
(actualtime=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)
(actualtime=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.036rows=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)
(actualtime=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.442rows=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)
(actualtime=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)
(actualtime=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.85rows=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.026rows=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.10rows=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=1width=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.007rows=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)
(actualtime=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)
(actualtime=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.093rows=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
Chris Kratz <chris.kratz@vistashare.com> writes:
> I'm struggling to get postgres to run a particular query quickly.
The key problem seems to be the join size misestimate here:
> -> 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)
> -> Hash (cost=19.21..19.21 rows=383 width=4) (actual time=0.513..0.513 rows=383 loops=1)
Evidently it's not realizing that every row of par will have a join
partner, but why not? I suppose a.activityid is unique, and in most
cases that I've seen the code seems to get that case right.
Would you show us the pg_stats rows for par.activity and a.activityid?
regards, tom lane
On Wednesday 17 October 2007 14:49, Tom Lane wrote: > Chris Kratz <chris.kratz@vistashare.com> writes: > > I'm struggling to get postgres to run a particular query quickly. > > The key problem seems to be the join size misestimate here: > > -> 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) -> Hash > > (cost=19.21..19.21 rows=383 width=4) (actual time=0.513..0.513 rows=383 > > loops=1) > > Evidently it's not realizing that every row of par will have a join > partner, but why not? I suppose a.activityid is unique, and in most > cases that I've seen the code seems to get that case right. > > Would you show us the pg_stats rows for par.activity and a.activityid? > > regards, tom lane > > ---------------------------(end of broadcast)--------------------------- > TIP 4: Have you searched our list archives? > > http://archives.postgresql.org Thanks for the reply and help Tom, activityid is unique on the activity table. activity on par is a child table to activity, with multiple rows per activityid. Here are the pg_stats rows for par.activity and a.activityid. # select * from pg_stats where tablename='activity' and attname='activityid'; schemaname | tablename | attname | null_frac | avg_width | n_distinct | most_common_vals | most_common_freqs | histogram_bounds | correlation ------------+-----------+------------+-----------+-----------+------------+------------------+-------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------- public | activity | activityid | 0 | 4 | -1 | | | {232,2497,3137,3854,4210,5282,9318,11396,12265,12495,12760,13509,13753,15000,15379,15661,16791,17230,17703,18427,18987,19449,19846,20322,20574,20926,21210,21501,21733,22276,22519,23262,24197,24512,24898,25616,25893,26175,26700,27141,27509,27759,29554,29819,30160,30699,32343,32975,33227,33493,33753,33980,34208,34534,34780,35007,35235,35641,35922,36315,36678,37998,38343,38667,39046,39316,39778,40314,40587,40884,41187,41860,42124,42399,42892,43313,43546,43802,45408,45740,46030,46406,46655,47031,47556,47881,48190,48528,48810,49038,49319,49704,49978,50543,50916,51857,52134,52380,52691,53011,53356} | 0.703852 (1 row) # select * from pg_stats where tablename='rpt_agencyquestioncache_171_0' and attname='activity'; schemaname | tablename | attname | null_frac | avg_width | n_distinct | most_common_vals | most_common_freqs | histogram_bounds | correlation ------------+-------------------------------+----------+-----------+-----------+------------+---------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------- public | rpt_agencyquestioncache_171_0 | activity | 0 | 4 | 248 | {32905,32910,32912,32909,33530,32906,32931,33839,33837,32943,35267,33832,35552,35550,42040,39167}| {0.1471,0.125533,0.1114,0.0935667,0.0903667,0.0538,0.0378,0.0347667,0.0342667,0.0292667,0.0256333,0.0245333,0.0142333,0.0128333,0.0110333,0.00883333} | {32911,32953,32955,33745,33791,33811,33812,33813,33817,33820,33825,33827,33836,33838,33838,33843,33852,33859,33860,33862,33868,33869,33870,33872,33872,33872,33874,33875,33877,33879,33880,33881,33884,33885,33886,33886,33894,33899,33899,33905,33907,33911,33912,33915,33926,35549,35551,35551,35715,35716,35716,35717,35727,35734,39262,42010,42015,42015,42015,42015,42032,42032,42032,42042,42042,42045,43107,43108,43110,43111,43114,44017,44017,44017,44017,45824,46370,46370,46371,46371,46372,46372,46373,46373,46374,46375,46376,46377,46377,46378,46379,46387,52175,52177,52195,52204,52229,52447,52451,52454,53029} | -0.44304 (1 row) -Chris
Chris Kratz <chris.kratz@vistashare.com> writes:
> On Wednesday 17 October 2007 14:49, Tom Lane wrote:
>> Evidently it's not realizing that every row of par will have a join
>> partner, but why not? I suppose a.activityid is unique, and in most
>> cases that I've seen the code seems to get that case right.
>>
>> Would you show us the pg_stats rows for par.activity and a.activityid?
> Here are the pg_stats rows for par.activity and a.activityid.
Hmm, nothing out of the ordinary there.
I poked at this a bit and realized that what seems to be happening is
that the a.programid = 171 condition is reducing the selectivity
estimate --- that is, it knows that that will filter out X percent of
the activity rows, and it assumes that *the size of the join result will
be reduced by that same percentage*, since join partners would then be
missing for some of the par rows. The fact that the join result doesn't
actually decrease in size at all suggests that there's some hidden
correlation between the programid condition and the condition on
par.provider_lfm. Is that true? Maybe you could eliminate one of the
two conditions from the query?
Since PG doesn't have any cross-table (or even cross-column) statistics
it's not currently possible for the optimizer to deal very well with
hidden correlations like this ...
regards, tom lane
Chris Kratz skrev: > 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.')) The first two join-conditions seem strange - I think those are the cause of the performance problems. The result of the first join, for instance, is the return of all rows from dem, and matching rows from par IFF dem.program_id =171 (NULLS otherwise). In fact, since you are using a condition on the par table, you could just as well use inner joins for the first two cases. Hope this helps, Nis
On Wednesday 17 October 2007 20:23, Tom Lane wrote: > Chris Kratz <chris.kratz@vistashare.com> writes: > > On Wednesday 17 October 2007 14:49, Tom Lane wrote: > >> Evidently it's not realizing that every row of par will have a join > >> partner, but why not? I suppose a.activityid is unique, and in most > >> cases that I've seen the code seems to get that case right. > >> > >> Would you show us the pg_stats rows for par.activity and a.activityid? > > > > Here are the pg_stats rows for par.activity and a.activityid. > > Hmm, nothing out of the ordinary there. > > I poked at this a bit and realized that what seems to be happening is > that the a.programid = 171 condition is reducing the selectivity > estimate --- that is, it knows that that will filter out X percent of > the activity rows, and it assumes that *the size of the join result will > be reduced by that same percentage*, since join partners would then be > missing for some of the par rows. The fact that the join result doesn't > actually decrease in size at all suggests that there's some hidden > correlation between the programid condition and the condition on > par.provider_lfm. Is that true? Maybe you could eliminate one of the > two conditions from the query? > > Since PG doesn't have any cross-table (or even cross-column) statistics > it's not currently possible for the optimizer to deal very well with > hidden correlations like this ... > > regards, tom lane > > ---------------------------(end of broadcast)--------------------------- > TIP 6: explain analyze is your friend Yes, you are correct. Programid is a "guard" condition to make sure a user cannot look at rows outside of their program. In this particular case the par table only has rows for this agency (at one point in time, all rows were in one table), so I was able to remove the check on programid on "a". This causes my example query to run in 200ms. That's wonderful. So, to recap. We had a filter on the join clause which really didn't in this case affect the selectivity of the join table. But the optimizer assumed that the selectivity would be affected causing it to think the join would generate only a few rows. Since it thought that there would be relatively few rows returned, it used a nestloop instead of another type of join that would have been faster with larger data sets. Thanks for all your help. -Chris