Optimizer(?) off by factor of 3 ... ?

"Marc G. Fournier" <scrappy@hub.org> writes:

-> Index Scan using clubs_idx on clubs c (cost=0.00..1695474.62 rows=26569 width=64) (actual time=0.48..1936.95 rows=23510 loops=1)

This indexscan cost estimate is completely out of whack, it would seem.

Have you done an ANALYZE on this table recently? If so, what do you get
from
select * from pg_stats where tablename = 'clubs';
select * from pg_class where relname = 'clubs';

regards, tom lane

On Mon, 11 Feb 2002, Tom Lane wrote:

"Marc G. Fournier" <scrappy@hub.org> writes:

-> Index Scan using clubs_idx on clubs c (cost=0.00..1695474.62 rows=26569 width=64) (actual time=0.48..1936.95 rows=23510 loops=1)

This indexscan cost estimate is completely out of whack, it would seem.

Have you done an ANALYZE on this table recently? If so, what do you get

Yup, been doing ANALYZEs just to make sure that I did them, so have done
several since this database/table was populated ...

from
select * from pg_stats where tablename = 'clubs';
select * from pg_class where relname = 'clubs';

tablename | attname | null_frac | avg_width | n_distinct | most_common_vals | most_common_freqs | !
histogram_bounds !
| correlation
-----------+---------------+-----------+-----------+------------+-----------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------!
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------!
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------
clubs | uid | 0 | 8 | -1 | | | {13,56847,365368,432334,482114,538111,627969,683193,738091,793220,841391} !
!
| 0.596839
clubs | club | 0 | 4 | 3 | {2,1,3} | {0.754,0.195333,0.0506667} | !
!
| 1
clubs | hide | 0 | 2 | 2 | {1,0} | {0.950667,0.0493333} | !
!
| 0.810325
clubs | last_update | 0 | 8 | 7731 | {1008005872,1009714469,1009688701,1011503100,1011330301,1009256700,1009429504,1011848704,1009885559,1010207101} | {0.735,0.004,0.00266667,0.00233333,0.002,0.00166667,0.00166667,0.00166667,0.00133333,0.00133333} | {1007584989,1008125462,1008569460,1009199787,1009651136,1010099882,1010466300,1010887647,1011224456,1011537512,1011853900} !
!
| 0.691723
clubs | category | 0 | 30 | 7 | {"{1,0,0,0,5}","{0,0,0,4,0}","{0,0,0,0,0}","{0,0,0,4,5}","{1,2,0,0,0}","{1,2,3,4,5}","{1,2,3,4,0}"} | {0.316333,0.268667,0.169,0.139333,0.056,0.0256667,0.025} | !
!
|
clubs | club_interest | 0 | 44 | 1 | {"{0,0,0,0,0,0,0,0,0,0,0,0}"} | {1} | !
!
|
clubs | headline | 0 | 28 | 27663 | {"","looking for fun",Hello,hi,Hi,hello,Looking,"Looking for fun",hey,"Hello Ladies"} | {0.103,0.00566667,0.004,0.004,0.00366667,0.00333333,0.00166667,0.00166667,0.00166667,0.00133333} | {" ANGEL EYES","Cum get sum","Hell-o Iam hear,take me away.","IF YOU LIKE A LAUGH IM YOU MAN THANX","Looking for a man with a Heart","Nice guy just looking to meet new people","Tall Dark & Handsome","come and say hi","im 6 180 brown brown luv sex makeing girls feel good","nice guy looking for a loving relationship with no games","��� looking good friend"} !
!
| -0.0150456
clubs | my_desc | 0 | 230 | 29320 | {""," "} | {0.103,0.001} | {"
<BR>
<BR> english speaking man searching for partner in norway near oslo
<BR>
<BR>
<BR> are single and miss you
<BR>
<BR>
<BR> lets share the lonely nights ","Drop me a line . U will not regret coz u just meet a chance of a lifetime ...Still thinking ?still wondering ? stop ! Write to me now and i'll get back to u !","I am 35. I love good sex. I enjoy candle light, showers, baths, oil massages, give and recieve. I don't need intercourse to be satisfied. I think you need to use your imagination if you don't.","I am intelligent,well-read,kind, emotional, have a good sense of humor. I dislike egoism,pettiness and dishonesty.","I'm 23 in Notting Hill, looking for a woman older or younger for an int!
imate secret encounter. I'm 5'11, dark hair, blue eyes, slim build. I regularly work out in the gym, and am ready to have a work out in you.","Im a hard working man who would like a very
<BR>sexy attractive women to share good times
<BR>with here in South Florida. Walks by the
<BR>Ocean, fine dining and just hanging out
<BR>together would be nice.","Not into ego trips or head games. I'm in a comfortable place in my life where I don't have to prove myself personally or professionally. I just desire to enjoy life and its many different venues.","blue eye red head - thus the name foxxy ... Looking for you to share whatever your hearts desire might be ...","i am single libyan man , friendship means more to me , so i long to do good and wide friendship , i wish all over the world , so if you want to talk with me this is my email
<BR>abdul_zr@yahoo.com","looking for fun and cassual sex with serious ladies 'your pleasure is mine also'if you want to get crazy and have real fun in a!
safe manner call me ",������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������nmcjdkf�����������������������������������������������������������������������������������������������������������������������������������������������������������������������������������} | -0.0011142
clubs | ur_desc | 0 | 4 | 1 | {""} | {1} | !
!
| 1
clubs | pictures | 0 | 26 | 2 | {"{0,0,0}","{1,0,0}"} | {0.889,0.111} | !
!
|
clubs | voice | 0 | 2 | 2 | {0,1} | {0.999333,0.000666667} | !
!
| 0.998169
(11 rows)

relname | reltype | relowner | relam | relfilenode | relpages | reltuples | reltoastrelid | reltoastidxid | relhasindex | relisshared | relkind | relnatts | relchecks | reltriggers | relukeys | relfkeys | relrefs | relhasoids | relhaspkey | relhasrules | relhassubclass | relacl
---------+---------+----------+-------+-------------+----------+-----------+---------------+---------------+-------------+-------------+---------+----------+-----------+-------------+----------+----------+---------+------------+------------+-------------+----------------+--------
clubs | 5535242 | 1003 | 0 | 5535241 | 25552 | 486011 | 5535243 | 0 | t | f | r | 11 | 0 | 0 | 0 | 0 | 0 | t | f | f | f |
(1 row)

And just in case it has relevance:

iwantu=# \d clubs_idx
Index "clubs_idx"
Column | Type
--------+---------
uid | bigint
club | integer
btree

I'm trying to work out how the planner arrived at the numbers you're
showing; the hashjoin cost estimate seems a little lower than I'd
expect. Are you using nonstandard values for any of the planner cost
factors? (cpu_operator_cost, etc) How about sort_mem?

regards, tom lane

the postgresql.conf file ... for testing, I used 'set enable_seqscan'
after the server was live to turn on/off, this is just hte default ...

tcpip_socket = true
max_connections = 200 # 1-1024
port = 5434
sort_mem = 4024
shared_buffers = 32768
fsync = false
wal_buffers = 32
debug_pretty_print = true
enable_seqscan = false

On Mon, 11 Feb 2002, Tom Lane wrote:

"Marc G. Fournier" <scrappy@hub.org> writes:

[ bogus optimizer choices in 7.2 ]

Well, I guess the good news is we seem to be past the old bugaboo of bad
statistics: the estimated row counts are all in the right ballpark. Now
we get to have fun with the cost models :-).

It looks to me like there are a couple of problems here. One is that
the default value of effective_cache_size is way too small --- it's set
at 1000, which is probably silly when you have NBuffers set to 32768.
(In hindsight maybe we should have expressed it as a multiple of
NBuffers rather than an absolute size.) You could tweak that with a
postgresql.conf change, but I'm not sure that that alone will help much.

The more difficult issue is that nestloops with inner indexscan are
being seriously misestimated. We're computing the cost as though each
iteration of the inner scan were completely independent and being done
from a standing start --- which is wrong, because in practice scans
after the first will tend to find buffer cache hits for pages already
read in by prior scans. You can bet, for example, that the btree
metapage and root page aren't going to need to be re-read on each
iteration.

I am thinking that the right way to do this is to cost the entire inner
indexscan (all iterations put together) as if it were a single
indexscan, at least for the purposes of applying the Mackert & Lohman
formula embedded in cost_index. That would give us a more realistic
result for the total cost of the main-table accesses driven by the
index. Not sure how to adjust the cost estimate for reading the index,
but clearly we need to make some adjustment for repeated hits on the
upper index pages.

This is probably a bigger change than we can hope to make in 7.2.* ...

BTW, what do you get if you EXPLAIN ANALYZE that orient/clubs join
with seqscan enabled and hashjoin disabled? If it's a mergejoin,
how about if you also disable mergejoin? It seems to me that a seqscan
on clubs would be a much better way to do the nestloop join than an
indexscan --- but it's being forced into an indexscan because you
disabled seqscan.

regards, tom lane

On Mon, 11 Feb 2002, Tom Lane wrote:

"Marc G. Fournier" <scrappy@hub.org> writes:

[ bogus optimizer choices in 7.2 ]

Well, I guess the good news is we seem to be past the old bugaboo of bad
statistics: the estimated row counts are all in the right ballpark. Now
we get to have fun with the cost models :-).

It looks to me like there are a couple of problems here. One is that
the default value of effective_cache_size is way too small --- it's set
at 1000, which is probably silly when you have NBuffers set to 32768.
(In hindsight maybe we should have expressed it as a multiple of
NBuffers rather than an absolute size.) You could tweak that with a
postgresql.conf change, but I'm not sure that that alone will help much.

The more difficult issue is that nestloops with inner indexscan are
being seriously misestimated. We're computing the cost as though each
iteration of the inner scan were completely independent and being done
from a standing start --- which is wrong, because in practice scans
after the first will tend to find buffer cache hits for pages already
read in by prior scans. You can bet, for example, that the btree
metapage and root page aren't going to need to be re-read on each
iteration.

I am thinking that the right way to do this is to cost the entire inner
indexscan (all iterations put together) as if it were a single
indexscan, at least for the purposes of applying the Mackert & Lohman
formula embedded in cost_index. That would give us a more realistic
result for the total cost of the main-table accesses driven by the
index. Not sure how to adjust the cost estimate for reading the index,
but clearly we need to make some adjustment for repeated hits on the
upper index pages.

This is probably a bigger change than we can hope to make in 7.2.* ...

BTW, what do you get if you EXPLAIN ANALYZE that orient/clubs join
with seqscan enabled and hashjoin disabled? If it's a mergejoin,
how about if you also disable mergejoin? It seems to me that a seqscan
on clubs would be a much better way to do the nestloop join than an
indexscan --- but it's being forced into an indexscan because you
disabled seqscan.

iwantu=# set enable_seqscan=true;
iwantu=# set enable_hashjoin=false;
iwantu=# explain analyze SELECT o.uid,headline,pictures,voice FROM orient o JOIN clubs c ON (o.uid = c.uid AND c.club = 1 AND ( c.hide ='1' OR c.hide='2' ) AND (o.female) );
NOTICE: QUERY PLAN:

Merge Join (cost=97750.86..100011.74 rows=78391 width=72) (actual time=17041.33..23771.57 rows=50745 loops=1)
-> Sort (cost=53412.61..53412.61 rows=422145 width=8) (actual time=12996.56..15563.59 rows=418951 loops=1)
-> Seq Scan on orient o (cost=0.00..7718.69 rows=422145 width=8) (actual time=0.02..3237.46 rows=418951 loops=1)
-> Sort (cost=44338.25..44338.25 rows=90251 width=64) (actual time=4044.65..4531.18 rows=76954 loops=1)
-> Seq Scan on clubs c (cost=0.00..34057.19 rows=90251 width=64) (actual time=0.04..1399.83 rows=76954 loops=1)
Total runtime: 24082.76 msec

iwantu=# set enable_mergejoin=false;
iwantu=# explain analyze SELECT o.uid,headline,pictures,voice FROM orient o JOIN clubs c ON (o.uid = c.uid AND c.club = 1 AND ( c.hide ='1' OR c.hide='2' ) AND (o.female) );
NOTICE: QUERY PLAN:

Nested Loop (cost=0.00..363373.00 rows=78391 width=72) (actual time=0.54..5488.15 rows=50745 loops=1)
-> Seq Scan on clubs c (cost=0.00..34057.19 rows=90251 width=64) (actual time=0.03..1434.97 rows=76954 loops=1)
-> Index Scan using orient_pkey on orient o (cost=0.00..3.64 rows=1 width=8) (actual time=0.03..0.03 rows=1 loops=76954)
Total runtime: 5769.21 msec

Okay, I've 'saved' the dataset/schema for this if you want me to test/try
anything further with it, as I'm going to try and redo teh schema to get
around the issues for now ...

On Mon, 11 Feb 2002, Tom Lane wrote: