Thread: Query performance discontinuity
pgsql-performers,
Just out of curiosity, anybody with any ideas on what happens to this
query when the limit is 59626? It's as though 59626 = infinity?
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59624;
NOTICE: QUERY PLAN:
Limit (cost=0.00..160328.37 rows=59624 width=179) (actual
time=14.52..2225.16 rows=59624 loops=1)
-> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935
width=179) (actual time=14.51..2154.59 rows=59625 loops=1)
Total runtime: 2265.93 msec
EXPLAIN
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59625;
NOTICE: QUERY PLAN:
Limit (cost=0.00..160331.06 rows=59625 width=179) (actual
time=0.45..2212.19 rows=59625 loops=1)
-> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935
width=179) (actual time=0.45..2140.87 rows=59626 loops=1)
Total runtime: 2254.50 msec
EXPLAIN
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59626;
NOTICE: QUERY PLAN:
Limit (cost=160332.32..160332.32 rows=59626 width=179) (actual
time=37359.41..37535.85 rows=59626 loops=1)
-> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual
time=37359.40..37471.07 rows=59627 loops=1)
-> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179)
(actual time=0.26..12433.00 rows=327960 loops=1)
Total runtime: 38477.39 msec
EXPLAIN
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59627;
NOTICE: QUERY PLAN:
Limit (cost=160332.32..160332.32 rows=59627 width=179) (actual
time=38084.85..38260.88 rows=59627 loops=1)
-> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual
time=38084.83..38194.63 rows=59628 loops=1)
-> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179)
(actual time=0.15..12174.74 rows=327960 loops=1)
Total runtime: 38611.83 msec
EXPLAIN
pganalysis=> \d ps2
Table "ps2"
Column | Type | Modifiers
-------------+--------------------------+-----------
host | character varying(255) |
pid | integer |
line | integer |
time_stamp | timestamp with time zone |
seq | integer |
cpu_sys | real |
cpu_elapsed | real |
cpu_user | real |
cpu_syst | real |
cpu_usert | real |
mssp | integer |
sigp | integer |
msrt | integer |
msst | integer |
sigt | integer |
msrp | integer |
swap | integer |
swat | integer |
recp | integer |
rect | integer |
pgfp | integer |
pgft | integer |
icsp | integer |
vcst | integer |
icst | integer |
vcsp | integer |
fsbop | integer |
fsbos | integer |
fsbip | integer |
fsbis | integer |
dread | integer |
dwrit | integer |
sbhr | real |
sread | integer |
swrit | integer |
lbhr | real |
lread | integer |
lwrit | integer |
dbuser | character(8) |
tstart | timestamp with time zone |
Indexes: ps2_idx
pganalysis=> \d ps2_idx
Index "ps2_idx"
Column | Type
------------+--------------------------
tstart | timestamp with time zone
time_stamp | timestamp with time zone
btree
pganalysis=>
psql (PostgreSQL) 7.2
contains support for: readline, history, multibyte
Platform: Celeron 1.3GHz, 512MB 40GB IDE hard disk, Linux 2.4.8-26mdk
kernel
Regards,
Mike
Mike, > Just out of curiosity, anybody with any ideas on what happens to this > query when the limit is 59626? It's as though 59626 = infinity? I'd suspect that this size has something to do with your system resources. have you tried this test on other hardware? BTW, my experience is that Celerons are dog-slow at anything involveing large or complex queries. Something to do with the crippled cache, I think. -- -Josh Berkus Aglio Database Solutions San Francisco
On 12 Nov 2002, Mike Nielsen wrote: > Just out of curiosity, anybody with any ideas on what happens to this > query when the limit is 59626? It's as though 59626 = infinity? > EXPLAIN > pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1 > 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > tstart,time_stamp limit 59625; > NOTICE: QUERY PLAN: > > Limit (cost=0.00..160331.06 rows=59625 width=179) (actual > time=0.45..2212.19 rows=59625 loops=1) > -> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935 > width=179) (actual time=0.45..2140.87 rows=59626 loops=1) > Total runtime: 2254.50 msec > > EXPLAIN > pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1 > 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > tstart,time_stamp limit 59626; > NOTICE: QUERY PLAN: > > Limit (cost=160332.32..160332.32 rows=59626 width=179) (actual > time=37359.41..37535.85 rows=59626 loops=1) > -> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual > time=37359.40..37471.07 rows=59627 loops=1) > -> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179) > (actual time=0.26..12433.00 rows=327960 loops=1) > Total runtime: 38477.39 msec This is apparently the breakpoint at which the sequence scan/sort/limit max cost seems to become lower than indexscan/limit given the small difference in estimated costs. What do you get with limit 59626 and enable_seqscan=off? My guess is that it's just above the 160332.32 estimated here. I believe that the query is using the index to avoid a sort, but possibly/probably not to do the condition. I'd wonder if analyzing with more buckets might get it a better idea, but I really don't know. Another option is to see what making an index on (time_stamp, tstart) gives you, but if most of the table meets the time_stamp condition, that wouldn't help any.
Stephan Szabo <sszabo@megazone23.bigpanda.com> writes:
>> pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
>> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
>> tstart,time_stamp limit 59625;
>> NOTICE: QUERY PLAN:
>>
>> Limit (cost=0.00..160331.06 rows=59625 width=179) (actual
>> time=0.45..2212.19 rows=59625 loops=1)
>> -> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935
>> width=179) (actual time=0.45..2140.87 rows=59626 loops=1)
>> Total runtime: 2254.50 msec
> I believe that the query is using the index to avoid a sort, but
> possibly/probably not to do the condition.
Certainly not to do the condition, because <> is not an indexable
operator. Would it be possible to express the tstart condition as
tstart > '2000-1-1 00:00:00' ?
The other thing that's pretty obvious is that the cost of the indexscan
plan is drastically overestimated relative to the seqscan/sort plan.
It might be worth experimenting with lowering random_page_cost to see
if that helps. I'm also curious to know whether the table is likely to
be nearly in order by tstart/time_stamp --- we know that the effects
of index-order correlation aren't modeled very well in 7.2.
Finally, it might be worth increasing sort_mem, if it's at the default
presently.
regards, tom lane
Stephan, Tom & Josh:
Here's the result I get from changing the <> to a > in the tstart
condition (no improvement):
pganalysis=> explain analyze select * from ps2 where tstart> '2000-1-1
pganalysis'> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
pganalysis-> tstart,time_stamp limit 59628;
NOTICE: QUERY PLAN:
Limit (cost=160313.27..160313.27 rows=59628 width=179) (actual
time=42269.87..42709.82 rows=59628 loops=1)
-> Sort (cost=160313.27..160313.27 rows=327895 width=179) (actual
time=42269.86..42643.74 rows=59629 loops=1)
-> Seq Scan on ps2 (cost=0.00..13783.40 rows=327895 width=179)
(actual time=0.15..15211.49 rows=327960 loops=1)
Total runtime: 43232.53 msec
EXPLAIN
Setting enable_seqscan=off produced a good result:
pganalysis=> explain analyze select * from ps2 where tstart> '2000-1-1
pganalysis'> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
pganalysis-> tstart,time_stamp limit 59628;
NOTICE: QUERY PLAN:
Limit (cost=0.00..160322.87 rows=59628 width=179) (actual
time=40.39..2222.06 rows=59628 loops=1)
-> Index Scan using ps2_idx on ps2 (cost=0.00..881616.45 rows=327895
width=179) (actual time=40.38..2151.38 rows=59629 loops=1)
Total runtime: 2262.23 msec
EXPLAIN
The ps2 table is in time_stamp order, but the tstarts aren't quite as
good -- they're mostly there, but they're computed by subtracting a
(stochastic) value from time_stamp.
I haven't tinkered with sort_mem yet, but will once I've got this little
project wrapped up (1 or 2 days to go!).
This, by the way, is pg log data that I've parsed up so I can do some
performance number-crunching for a client of mine. Is there a better
way to get comprehensive, per-query read, write and cache hit data? As
you can imagine, with millions of records, my client-side perl script
for the parsing is slow. I've tried my hand at writing an aggregate
function on the server side using lex and yacc, but decided that, at
least for this project, I'd rather let the machine do the head-banging
-- I can tokenize the raw syslog data (loaded into another pg table)
into an intermediate result in an aggregate function, and my parser
works on the token strings, but the perl script finished before I could
go any further...
In the off chance, however, that I get invited to more of this kind of
work, it would be really handy to be able to get the data without all
this hassle! Any clues would be gratefully received.
Regards,
Mike
On Tue, 2002-11-12 at 04:44, Mike Nielsen wrote:
pgsql-performers,
Just out of curiosity, anybody with any ideas on what happens to this
query when the limit is 59626? It's as though 59626 = infinity?
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59624;
NOTICE: QUERY PLAN:
Limit (cost=0.00..160328.37 rows=59624 width=179) (actual
time=14.52..2225.16 rows=59624 loops=1)
-> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935
width=179) (actual time=14.51..2154.59 rows=59625 loops=1)
Total runtime: 2265.93 msec
EXPLAIN
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59625;
NOTICE: QUERY PLAN:
Limit (cost=0.00..160331.06 rows=59625 width=179) (actual
time=0.45..2212.19 rows=59625 loops=1)
-> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935
width=179) (actual time=0.45..2140.87 rows=59626 loops=1)
Total runtime: 2254.50 msec
EXPLAIN
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59626;
NOTICE: QUERY PLAN:
Limit (cost=160332.32..160332.32 rows=59626 width=179) (actual
time=37359.41..37535.85 rows=59626 loops=1)
-> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual
time=37359.40..37471.07 rows=59627 loops=1)
-> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179)
(actual time=0.26..12433.00 rows=327960 loops=1)
Total runtime: 38477.39 msec
EXPLAIN
pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1
00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
tstart,time_stamp limit 59627;
NOTICE: QUERY PLAN:
Limit (cost=160332.32..160332.32 rows=59627 width=179) (actual
time=38084.85..38260.88 rows=59627 loops=1)
-> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual
time=38084.83..38194.63 rows=59628 loops=1)
-> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179)
(actual time=0.15..12174.74 rows=327960 loops=1)
Total runtime: 38611.83 msec
EXPLAIN
pganalysis=> \d ps2
Table "ps2"
Column | Type | Modifiers
-------------+--------------------------+-----------
host | character varying(255) |
pid | integer |
line | integer |
time_stamp | timestamp with time zone |
seq | integer |
cpu_sys | real |
cpu_elapsed | real |
cpu_user | real |
cpu_syst | real |
cpu_usert | real |
mssp | integer |
sigp | integer |
msrt | integer |
msst | integer |
sigt | integer |
msrp | integer |
swap | integer |
swat | integer |
recp | integer |
rect | integer |
pgfp | integer |
pgft | integer |
icsp | integer |
vcst | integer |
icst | integer |
vcsp | integer |
fsbop | integer |
fsbos | integer |
fsbip | integer |
fsbis | integer |
dread | integer |
dwrit | integer |
sbhr | real |
sread | integer |
swrit | integer |
lbhr | real |
lread | integer |
lwrit | integer |
dbuser | character(8) |
tstart | timestamp with time zone |
Indexes: ps2_idx
pganalysis=> \d ps2_idx
Index "ps2_idx"
Column | Type
------------+--------------------------
tstart | timestamp with time zone
time_stamp | timestamp with time zone
btree
pganalysis=>
psql (PostgreSQL) 7.2
contains support for: readline, history, multibyte
Platform: Celeron 1.3GHz, 512MB 40GB IDE hard disk, Linux 2.4.8-26mdk
kernel
Regards,
Mike
---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster
Given the estimated costs, PostgreSQL is doing the right things. However, in your case, it doesn't appear that the estimations are realistic. Index scans are much cheaper than advertised. Try setting your random_page_cost lower (1.5 to 2 rather than 4). Bumping sortmem to 32 or 64MB (if plenty of ram is available) will help most situations. Might see the 'pg_autotune' project for assistance in picking good values. http://gborg.postgresql.org/project/pgautotune/projdisplay.php On Mon, 2002-11-11 at 23:10, Mike Nielsen wrote: > Stephan, Tom & Josh: > > Here's the result I get from changing the <> to a > in the tstart > condition (no improvement): > > pganalysis=> explain analyze select * from ps2 where tstart> '2000-1-1 > pganalysis'> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > pganalysis-> tstart,time_stamp limit 59628; > NOTICE: QUERY PLAN: > > Limit (cost=160313.27..160313.27 rows=59628 width=179) (actual > time=42269.87..42709.82 rows=59628 loops=1) > -> Sort (cost=160313.27..160313.27 rows=327895 width=179) (actual > time=42269.86..42643.74 rows=59629 loops=1) > -> Seq Scan on ps2 (cost=0.00..13783.40 rows=327895 width=179) > (actual time=0.15..15211.49 rows=327960 loops=1) > Total runtime: 43232.53 msec > > EXPLAIN > > Setting enable_seqscan=off produced a good result: > > > pganalysis=> explain analyze select * from ps2 where tstart> '2000-1-1 > pganalysis'> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > pganalysis-> tstart,time_stamp limit 59628; > NOTICE: QUERY PLAN: > > Limit (cost=0.00..160322.87 rows=59628 width=179) (actual > time=40.39..2222.06 rows=59628 loops=1) > -> Index Scan using ps2_idx on ps2 (cost=0.00..881616.45 rows=327895 > width=179) (actual time=40.38..2151.38 rows=59629 loops=1) > Total runtime: 2262.23 msec > > EXPLAIN > > The ps2 table is in time_stamp order, but the tstarts aren't quite as > good -- they're mostly there, but they're computed by subtracting a > (stochastic) value from time_stamp. > > I haven't tinkered with sort_mem yet, but will once I've got this little > project wrapped up (1 or 2 days to go!). > > This, by the way, is pg log data that I've parsed up so I can do some > performance number-crunching for a client of mine. Is there a better > way to get comprehensive, per-query read, write and cache hit data? As > you can imagine, with millions of records, my client-side perl script > for the parsing is slow. I've tried my hand at writing an aggregate > function on the server side using lex and yacc, but decided that, at > least for this project, I'd rather let the machine do the head-banging > -- I can tokenize the raw syslog data (loaded into another pg table) > into an intermediate result in an aggregate function, and my parser > works on the token strings, but the perl script finished before I could > go any further... > > In the off chance, however, that I get invited to more of this kind of > work, it would be really handy to be able to get the data without all > this hassle! Any clues would be gratefully received. > > Regards, > > Mike > > > On Tue, 2002-11-12 at 04:44, Mike Nielsen wrote: > pgsql-performers, > > Just out of curiosity, anybody with any ideas on what happens to this > query when the limit is 59626? It's as though 59626 = infinity? > > pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1 > 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > tstart,time_stamp limit 59624; > NOTICE: QUERY PLAN: > > Limit (cost=0.00..160328.37 rows=59624 width=179) (actual > time=14.52..2225.16 rows=59624 loops=1) > -> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935 > width=179) (actual time=14.51..2154.59 rows=59625 loops=1) > Total runtime: 2265.93 msec > > EXPLAIN > pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1 > 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > tstart,time_stamp limit 59625; > NOTICE: QUERY PLAN: > > Limit (cost=0.00..160331.06 rows=59625 width=179) (actual > time=0.45..2212.19 rows=59625 loops=1) > -> Index Scan using ps2_idx on ps2 (cost=0.00..881812.85 rows=327935 > width=179) (actual time=0.45..2140.87 rows=59626 loops=1) > Total runtime: 2254.50 msec > > EXPLAIN > pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1 > 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > tstart,time_stamp limit 59626; > NOTICE: QUERY PLAN: > > Limit (cost=160332.32..160332.32 rows=59626 width=179) (actual > time=37359.41..37535.85 rows=59626 loops=1) > -> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual > time=37359.40..37471.07 rows=59627 loops=1) > -> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179) > (actual time=0.26..12433.00 rows=327960 loops=1) > Total runtime: 38477.39 msec > > EXPLAIN > pganalysis=> explain analyze select * from ps2 where tstart<> '2000-1-1 > 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > tstart,time_stamp limit 59627; > NOTICE: QUERY PLAN: > > Limit (cost=160332.32..160332.32 rows=59627 width=179) (actual > time=38084.85..38260.88 rows=59627 loops=1) > -> Sort (cost=160332.32..160332.32 rows=327935 width=179) (actual > time=38084.83..38194.63 rows=59628 loops=1) > -> Seq Scan on ps2 (cost=0.00..13783.52 rows=327935 width=179) > (actual time=0.15..12174.74 rows=327960 loops=1) > Total runtime: 38611.83 msec > > EXPLAIN > > pganalysis=> \d ps2 > Table "ps2" > Column | Type | Modifiers > -------------+--------------------------+----------- > host | character varying(255) | > pid | integer | > line | integer | > time_stamp | timestamp with time zone | > seq | integer | > cpu_sys | real | > cpu_elapsed | real | > cpu_user | real | > cpu_syst | real | > cpu_usert | real | > mssp | integer | > sigp | integer | > msrt | integer | > msst | integer | > sigt | integer | > msrp | integer | > swap | integer | > swat | integer | > recp | integer | > rect | integer | > pgfp | integer | > pgft | integer | > icsp | integer | > vcst | integer | > icst | integer | > vcsp | integer | > fsbop | integer | > fsbos | integer | > fsbip | integer | > fsbis | integer | > dread | integer | > dwrit | integer | > sbhr | real | > sread | integer | > swrit | integer | > lbhr | real | > lread | integer | > lwrit | integer | > dbuser | character(8) | > tstart | timestamp with time zone | > Indexes: ps2_idx > > pganalysis=> \d ps2_idx > Index "ps2_idx" > Column | Type > ------------+-------------------------- > tstart | timestamp with time zone > time_stamp | timestamp with time zone > btree > > pganalysis=> > > psql (PostgreSQL) 7.2 > contains support for: readline, history, multibyte > > > Platform: Celeron 1.3GHz, 512MB 40GB IDE hard disk, Linux 2.4.8-26mdk > kernel > > Regards, > > Mike > > > > ---------------------------(end of broadcast)--------------------------- > TIP 4: Don't 'kill -9' the postmaster > > > > ---------------------------(end of broadcast)--------------------------- > TIP 4: Don't 'kill -9' the postmaster > -- Rod Taylor
Mike, > Given the estimated costs, PostgreSQL is doing the right things. > > However, in your case, it doesn't appear that the estimations are > realistic. Index scans are much cheaper than advertised. Can I assume that you've run VACUUM FULL ANALYZE on the table, or preferably the whole database? > > Try setting your random_page_cost lower (1.5 to 2 rather than 4). > Bumping sortmem to 32 or 64MB (if plenty of ram is available) will > help > most situations. > > Might see the 'pg_autotune' project for assistance in picking good > values. > > http://gborg.postgresql.org/project/pgautotune/projdisplay.php Um. I don't think we have anything to advertise yet, for pg_autotune. It's still very much an alpha, and the limits we set are pretty arbitrary. -Josh Berkus
Hi, Josh.
Yes, I'd run a VACUUM FULL ANALYZE -- I did it again just to make sure,
and re-ran the query (similar result):
pganalysis=> explain analyze select * from ps2 where tstart> '2000-1-1
pganalysis'> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by
pganalysis-> tstart,time_stamp limit 59628;
NOTICE: QUERY PLAN:
Limit (cost=160313.27..160313.27 rows=59628 width=179) (actual
time=45405.47..46320.12 rows=59628 loops=1)
-> Sort (cost=160313.27..160313.27 rows=327895 width=179) (actual
time=45405.46..46248.31 rows=59629 loops=1)
-> Seq Scan on ps2 (cost=0.00..13783.40 rows=327895 width=179)
(actual time=13.52..17111.66 rows=327960 loops=1)
Total runtime: 46894.21 msec
EXPLAIN
Unfortunately, I have not yet had time to experiment with twiddling the
query optimizer parameters or memory -- my apologies for this, but,
well, a guy's gotta eat...
Regards,
Mike
On Wed, 2002-11-13 at 03:57, Josh Berkus wrote:
> Mike,
>
> > Given the estimated costs, PostgreSQL is doing the right things.
> >
> > However, in your case, it doesn't appear that the estimations are
> > realistic. Index scans are much cheaper than advertised.
>
> Can I assume that you've run VACUUM FULL ANALYZE on the table, or
> preferably the whole database?
>
> >
> > Try setting your random_page_cost lower (1.5 to 2 rather than 4).
> > Bumping sortmem to 32 or 64MB (if plenty of ram is available) will
> > help
> > most situations.
> >
> > Might see the 'pg_autotune' project for assistance in picking good
> > values.
> >
> > http://gborg.postgresql.org/project/pgautotune/projdisplay.php
>
> Um. I don't think we have anything to advertise yet, for pg_autotune.
> It's still very much an alpha, and the limits we set are pretty
> arbitrary.
>
> -Josh Berkus
--
Mike Nielsen <miken@bigpond.net.au>
Mike, > Yes, I'd run a VACUUM FULL ANALYZE -- I did it again just to make sure, > and re-ran the query (similar result): > > pganalysis=> explain analyze select * from ps2 where tstart> '2000-1-1 > pganalysis'> 00:00:00' and time_stamp > '2000-1-1 00:00:00' order by > pganalysis-> tstart,time_stamp limit 59628; > NOTICE: QUERY PLAN: > > Limit (cost=160313.27..160313.27 rows=59628 width=179) (actual > time=45405.47..46320.12 rows=59628 loops=1) > -> Sort (cost=160313.27..160313.27 rows=327895 width=179) (actual > time=45405.46..46248.31 rows=59629 loops=1) > -> Seq Scan on ps2 (cost=0.00..13783.40 rows=327895 width=179) > (actual time=13.52..17111.66 rows=327960 loops=1) > Total runtime: 46894.21 msec > > EXPLAIN > > Unfortunately, I have not yet had time to experiment with twiddling the > query optimizer parameters or memory -- my apologies for this, but, > well, a guy's gotta eat... Well, I''ll just concur with what others have said: for some reason, the parser is slightly underestimateing the cost of a seq scan, and dramatically overestimating the cost of an index scan, for this query. Other than tweaking to parser calculation values, I'd suggest dropping and re-building the index just for thouroughness. -- -Josh Berkus Aglio Database Solutions San Francisco
On Fri, 15 Nov 2002 03:26:32 +0000 (UTC), in
comp.databases.postgresql.performance you wrote:
> -> Seq Scan on ps2 (cost=0.00..13783.40 rows=327895 width=179)
^^^^^
>(actual time=0.15..15211.49 rows=327960 loops=1)
>
> -> Index Scan using ps2_idx on ps2 (cost=0.00..881616.45 rows=327895
^^^^^^
>width=179) (actual time=40.38..2151.38 rows=59629 loops=1)
^^^^
>
>The ps2 table is in time_stamp order, but the tstarts aren't quite as
>good -- they're mostly there, but they're computed by subtracting a
>(stochastic) value from time_stamp.
Mike,
this is the well known "divide correlation by number of index columns"
effect. This effect can be masked to a certain degree by reducing
random_page_cost, as has already been suggested.
The estimated index scan cost is also influenced by
effective_cache_size; its default value is 1000. Try
SET effective_cache_size = 50000;
This should help a bit, but please don't expect a big effect.
I'm running Postgres 7.2 with a modified index cost estimator here.
The patch is at http://www.pivot.at/pg/16-correlation.diff
This patch gives you two new GUC variables.
index_cost_algorithm: allows you to select between different methods
of interpolating between best case and worst case. 0 is the standard
behavior (before the patch), 1 to 4 tend more and more towards lower
index scan costs. See the switch statement in costsize.c for details.
Default = 3.
secondary_correlation: is a factor that is used to reduce the
correlation of the first index column a little bit once for each
additional index column. Default = 0.95.
With default settings you should get an index cost estimate between
20000 and 30000. Which allows you to increase random_page_cost to a
more reasonable value of something like 10 or even higher.
If you try it, please let me know how it works for you.
Servus
Manfred
v7.2.3 versus v7.3 -> huge performance penalty for JOIN with UNION
From
"ir. F.T.M. van Vugt bc."
Date:
L.S.
The query below runs 10-20 times slower under v7.3 than it did under v7.2.3:
- hardware is the same
- standard install of postgresql, both version had stats-collection enabled
- v7.2.3 had no multibyte and no locale, obviously v7.3 does
- *very* recent vacuum analyse
I expected some overhead due to the enabled mulitbyte, but not this much.. ;(
BTW, there are a few other queries that are performing *real* slow, but I'm
hoping this one will give away a cause for the overall problem...
Could anybody offer an idea?
trial=# explain analyse select foo.*, c.id from
(select *, 't' from lijst01_table union all
select *, 't' from lijst02_table union all
select *, 'f' from lijst03_table union all
select *, 'f' from lijst04_table union all
select *, 't' from lijst04b_table ) as foo
inner join creditor c
on foo.dflt_creditor_id = c.old_creditor_id
order by old_id;
* foo.dflt_creditor_id is of type varchar(20)
* c.old_creditor_id is of type text
The plan below shows something weird is happening during the join, but I can't
explain it.
TIA,
Frank.
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=54103.74..54116.18 rows=4976 width=498) (actual
time=234595.27..234607.58 rows=4976 loops=1)
Sort Key: foo.old_id
-> Nested Loop (cost=0.00..53798.19 rows=4976 width=498) (actual
time=7559.20..234476.70 rows=4976 loops=1)
Join Filter: ("inner".dflt_creditor_id =
("outer".old_creditor_id)::text)
-> Seq Scan on creditor c (cost=0.00..8.27 rows=227 width=14)
(actual time=0.05..7.35 rows=227 loops=1)
-> Subquery Scan foo (cost=0.00..174.76 rows=4976 width=150)
(actual time=0.25..969.47 rows=4976 loops=227)
-> Append (cost=0.00..174.76 rows=4976 width=150) (actual
time=0.20..658.14 rows=4976 loops=227)
-> Subquery Scan "*SELECT* 1" (cost=0.00..2.46 rows=46
width=145) (actual time=0.19..6.26 rows=46 loops=227)
-> Seq Scan on lijst01_table (cost=0.00..2.46
rows=46 width=145) (actual time=0.10..3.40 rows=46 loops=227)
-> Subquery Scan "*SELECT* 2" (cost=0.00..30.62
rows=862 width=150) (actual time=0.16..111.38 rows=862 loops=227)
-> Seq Scan on lijst02_table (cost=0.00..30.62
rows=862 width=150) (actual time=0.09..59.79 rows=862 loops=227)
-> Subquery Scan "*SELECT* 3" (cost=0.00..48.63
rows=1363 width=148) (actual time=0.16..166.98 rows=1363 loops=227)
-> Seq Scan on lijst03_table (cost=0.00..48.63
rows=1363 width=148) (actual time=0.09..87.45 rows=1363 loops=227)
-> Subquery Scan "*SELECT* 4" (cost=0.00..92.03
rows=2703 width=134) (actual time=0.15..338.66 rows=2703 loops=227)
-> Seq Scan on lijst04_table (cost=0.00..92.03
rows=2703 width=134) (actual time=0.09..176.41 rows=2703 loops=227)
-> Subquery Scan "*SELECT* 5" (cost=0.00..1.02 rows=2
width=134) (actual time=0.16..0.28 rows=2 loops=227)
-> Seq Scan on lijst04b_table (cost=0.00..1.02
rows=2 width=134) (actual time=0.09..0.16 rows=2 loops=227)
Total runtime: 234624.07 msec
(18 rows)
On Mon, Dec 02, 2002 at 04:45:55PM +0100, ir. F.T.M. van Vugt bc. wrote:
> L.S.
>
> The query below runs 10-20 times slower under v7.3 than it did under v7.2.3:
> - v7.2.3 had no multibyte and no locale, obviously v7.3 does
Are you using the C locale? If it was not enabled in 7.2.3, I
believe it was using C anyway; if you have some other locale, it's
now getting picked up, and that might be the source of the slower
performance (?).
A
--
----
Andrew Sullivan 204-4141 Yonge Street
Liberty RMS Toronto, Ontario Canada
<andrew@libertyrms.info> M2P 2A8
+1 416 646 3304 x110
"ir. F.T.M. van Vugt bc." <ftm.van.vugt@foxi.nl> writes:
> The query below runs 10-20 times slower under v7.3 than it did under v7.2.3:
I don't suppose you have explain output for it from 7.2.3?
It seems strange to me that the thing is picking a nestloop join here.
Either merge or hash would make more sense ... oh, but wait:
> inner join creditor c
> on foo.dflt_creditor_id = c.old_creditor_id
> * foo.dflt_creditor_id is of type varchar(20)
> * c.old_creditor_id is of type text
IIRC, merge and hash only work on plain Vars --- the implicit type
coercion from varchar to text is what's putting the kibosh on a more
intelligent join plan. Can you fix your table declarations to agree
on the datatype? If you don't want to change the tables, another
possibility is something like
select foo.*, c.id from
(select *, dflt_creditor_id::text as key, 't' from lijst01_table union all
select *, dflt_creditor_id::text as key, 't' from lijst02_table union all
select *, dflt_creditor_id::text as key, 'f' from lijst03_table union all
select *, dflt_creditor_id::text as key, 'f' from lijst04_table union all
select *, dflt_creditor_id::text as key, 't' from lijst04b_table ) as foo
inner join creditor c
on foo.key = c.old_creditor_id
order by old_id;
ie, force the type coercion to occur down inside the union, not at the
join.
This doesn't explain the slowdown from 7.2.3, though --- it had the same
deficiency. (I am hoping to get around to fixing it for 7.4.)
It could easy be that --enable-locale explains the slowdown. Are you
running 7.4 in C locale, or something else? Comparisons in locales
like en_US can be *way* slower than in C locale. You can use
pg_controldata to check this for sure.
regards, tom lane
Re: v7.2.3 versus v7.3 -> huge performance penalty for JOIN with UNION
From
"ir. F.T.M. van Vugt bc."
Date:
Wow, the speed at which you guys are responding never ceases to amaze me !
TL> I don't suppose you have explain output for it from 7.2.3?
Nope, sorry 'bout that.
BTW, the performance comparison was not a 'hard' (measured) number, but a
watch-timed conclusion on a complete run of a conversiontool this query is
part of.
TL> It seems strange to me that the thing is picking a nestloop join here.
TL> oh, but wait: the implicit type coercion from varchar to text is what's
TL> putting the kibosh on a more intelligent join plan.
You're abolutely right, I'm back in business when putting a type coercion
inside the union:
trial=# explain select foo.*, c.id from
<cut>
QUERY PLAN
-------------------------------------------------------------------------------------------------
Sort (cost=588.66..601.10 rows=4976 width=530)
Sort Key: foo.old_id
-> Hash Join (cost=8.84..283.12 rows=4976 width=530)
Hash Cond: ("outer"."key" = "inner".old_creditor_id)
-> Subquery Scan foo (cost=0.00..174.76 rows=4976 width=150)
-> Append (cost=0.00..174.76 rows=4976 width=150)
<cut>
(as opposed to: (cost=54103.74..54116.18 rows=4976 width=498))
> This doesn't explain the slowdown from 7.2.3, though --- it had the same
> deficiency. (I am hoping to get around to fixing it for 7.4.)
Mmm, that's weird. Could be caused by somebody over here who has done 'work'
on some queries... ;( => I'll check on that, if I can be absolutely sure the
7.2.3 version planned *this* query differently, I'll let you know. Sorry
'bout that....
AS> It could easy be that --enable-locale explains the slowdown. Are you
AS> running 7.4 in C locale, or something else?
On v7.2.3. I wasn't doing anything with locale.
The v7.3 put 'POSIX' into the postgresql.conf file, changing that into 'C'
didn't seem to make any difference.
AS> Comparisons in locales like en_US can be *way* slower than in C locale.
AS> You can use pg_controldata to check this for sure.
O.K. this seems to help a lot as well !
I'll have to take a look at both ISO C and POSIX locale, 'cause I wouldn't
have expected it to make such a difference...
On the original v7.3, pg_controldata returned 'posix', upon changing the
postgresql.conf it confirmed the change to 'C'. This resulted in:
POSIX_trial=# explain analyse select foo.*, c.id from
<cut>
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=588.66..601.10 rows=4976 width=530) (actual time=2482.51..2530.54
rows=4976 loops=1)
<cut>
Total runtime: 2636.15 msec
C_trial=# explain analyse select foo.*, c.id from
<cut>
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=588.66..601.10 rows=4976 width=530) (actual time=1537.05..1549.34
rows=4976 loops=1)
<cut>
Total runtime: 1567.76 msec
Hey, I'm happy ;-)
Thanks a lot !!!
Frank.