pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedIncorrect estimates on columns
6+ messages / 3 participants
[nested] [flat]
* Incorrect estimates on columns
@ 2007-10-17 17:34 Chris Kratz <chris.kratz@vistashare.com>
0 siblings, 2 replies; 6+ messages in thread
From: Chris Kratz @ 2007-10-17 17:34 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Incorrect estimates on columns
@ 2007-10-17 18:49 Tom Lane <tgl@sss.pgh.pa.us>
parent: Chris Kratz <chris.kratz@vistashare.com>
1 sibling, 1 reply; 6+ messages in thread
From: Tom Lane @ 2007-10-17 18:49 UTC (permalink / raw)
To: Chris Kratz <chris.kratz@vistashare.com>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Incorrect estimates on columns
@ 2007-10-17 19:43 Chris Kratz <chris.kratz@vistashare.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 6+ messages in thread
From: Chris Kratz @ 2007-10-17 19:43 UTC (permalink / raw)
To: pgsql-performance; +Cc: Tom Lane <tgl@sss.pgh.pa.us>
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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Incorrect estimates on columns
@ 2007-10-18 00:23 Tom Lane <tgl@sss.pgh.pa.us>
parent: Chris Kratz <chris.kratz@vistashare.com>
0 siblings, 1 reply; 6+ messages in thread
From: Tom Lane @ 2007-10-18 00:23 UTC (permalink / raw)
To: Chris Kratz <chris.kratz@vistashare.com>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Incorrect estimates on columns
@ 2007-10-18 09:29 Nis Jørgensen <nis@superlativ.dk>
parent: Chris Kratz <chris.kratz@vistashare.com>
1 sibling, 0 replies; 6+ messages in thread
From: Nis Jørgensen @ 2007-10-18 09:29 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: Incorrect estimates on columns
@ 2007-10-18 20:03 Chris Kratz <chris.kratz@vistashare.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 0 replies; 6+ messages in thread
From: Chris Kratz @ 2007-10-18 20:03 UTC (permalink / raw)
To: pgsql-performance; +Cc: Tom Lane <tgl@sss.pgh.pa.us>
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
^ permalink raw reply [nested|flat] 6+ messages in thread
end of thread, other threads:[~2007-10-18 20:03 UTC | newest]
Thread overview: 6+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2007-10-17 17:34 Incorrect estimates on columns Chris Kratz <chris.kratz@vistashare.com>
2007-10-17 18:49 ` Tom Lane <tgl@sss.pgh.pa.us>
2007-10-17 19:43 ` Chris Kratz <chris.kratz@vistashare.com>
2007-10-18 00:23 ` Tom Lane <tgl@sss.pgh.pa.us>
2007-10-18 20:03 ` Chris Kratz <chris.kratz@vistashare.com>
2007-10-18 09:29 ` Nis Jørgensen <nis@superlativ.dk>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox