CREATE INDEX speeds up query on 31 row table ...
Josh asked me to post this, since it was just "odd" ... I have
pg_autovacuum running on the table, with output looking for it looking
like:
[2004-09-30 02:29:47 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 02:35:11 PM] Performing: ANALYZE "public"."shown"
[2004-09-30 02:40:22 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 02:45:54 PM] Performing: ANALYZE "public"."shown"
[2004-09-30 02:51:03 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 02:56:29 PM] Performing: ANALYZE "public"."shown"
[2004-09-30 03:01:44 PM] Performing: VACUUM ANALYZE "public"."shown"
Its a *very* busy table ... and running on a 7.4.0 database ...
With:
explain analyze SELECT b.banner_id, b.filename, b.option_lvl, b.redirect_url
FROM banner b, shown s
WHERE b.start_date <= now()
AND ( b.end_date >= now() OR b.end_date IS NULL )
AND b.banner_id = s.banner_id
AND s.counter = ( SELECT min(counter)
FROM shown s, banner b
WHERE b.banner_id = s.banner_id
AND ( b.end_date >= now() OR b.end_date IS NULL ) )
LIMIT 1;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=123.27..155.21 rows=1 width=50) (actual time=3.630..3.635 rows=1 loops=1)
InitPlan
-> Aggregate (cost=123.27..123.27 rows=1 width=8) (actual time=2.808..2.814 rows=1 loops=1)
-> Merge Join (cost=2.15..123.20 rows=28 width=8) (actual time=0.615..2.528 rows=26 loops=1)
Merge Cond: ("outer".banner_id = "inner".banner_id)
-> Index Scan using banner_id_shown on shown s (cost=0.00..137.78 rows=32 width=12) (actual time=0.024..1.024 rows=32 loops=1)
-> Sort (cost=2.15..2.22 rows=28 width=4) (actual time=0.554..0.833 rows=26 loops=1)
Sort Key: b.banner_id
-> Seq Scan on banner b (cost=0.00..1.48 rows=28 width=4) (actual time=0.041..0.280 rows=26 loops=1)
Filter: ((end_date >= now()) OR (end_date IS NULL))
-> Nested Loop (cost=0.00..63.87 rows=2 width=50) (actual time=3.615..3.615 rows=1 loops=1)
-> Seq Scan on banner b (cost=0.00..1.64 rows=10 width=50) (actual time=0.042..0.042 rows=1 loops=1)
Filter: ((start_date <= now()) AND ((end_date >= now()) OR (end_date IS NULL)))
-> Index Scan using banner_id_shown on shown s (cost=0.00..6.21 rows=1 width=4) (actual time=3.537..3.537 rows=1 loops=1)
Index Cond: ("outer".banner_id = s.banner_id)
Filter: (counter = $0)
Total runtime: 3.929 ms
(17 rows)
Without:
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------
Limit (cost=2693.02..4038.17 rows=1 width=50) (actual time=190.296..190.302 rows=1 loops=1)
InitPlan
-> Aggregate (cost=2691.38..2691.38 rows=1 width=8) (actual time=161.848..161.853 rows=1 loops=1)
-> Hash Join (cost=1.55..2691.31 rows=28 width=8) (actual time=1.299..161.558 rows=26 loops=1)
Hash Cond: ("outer".banner_id = "inner".banner_id)
-> Seq Scan on shown s (cost=0.00..2689.32 rows=32 width=12) (actual time=0.007..160.087 rows=32 loops=1)
-> Hash (cost=1.48..1.48 rows=28 width=4) (actual time=0.466..0.466 rows=0 loops=1)
-> Seq Scan on banner b (cost=0.00..1.48 rows=28 width=4) (actual time=0.062..0.276 rows=26 loops=1)
Filter: ((end_date >= now()) OR (end_date IS NULL))
-> Nested Loop (cost=1.64..2691.94 rows=2 width=50) (actual time=190.281..190.281 rows=1 loops=1)
Join Filter: ("inner".banner_id = "outer".banner_id)
-> Seq Scan on shown s (cost=0.00..2689.40 rows=4 width=4) (actual time=189.326..189.326 rows=1 loops=1)
Filter: (counter = $0)
-> Materialize (cost=1.64..1.74 rows=10 width=50) (actual time=0.237..0.769 rows=23 loops=1)
-> Seq Scan on banner b (cost=0.00..1.64 rows=10 width=50) (actual time=0.131..0.394 rows=23 loops=1)
Filter: ((start_date <= now()) AND ((end_date >= now()) OR (end_date IS NULL)))
Total runtime: 190.510 ms
(17 rows)
banners=# select count(*) from shown;
count
-------
32
(1 row)
----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664
"Marc G. Fournier" <scrappy@postgresql.org> writes:
Its a *very* busy table ... and running on a 7.4.0 database ...
I wonder how many tuples are really in this table. Almost all of the 190ms is
spent in the two sequential scans of it. Which is an awful lot of time for a
32 tuple table.
You say it's "*very* busy" is it possible there are hundreds or thousands of
tuples in there that are uncommitted or committed after this query starts?
Alternatively, try a "vacuum full". If that helps then autovacuum is having
trouble keeping up with the rate of creation of dead tuples. You would have to
increase the FSM parameters.
Presumably autovacuum has warnings when it detects that scenario?
--
greg
Greg Stark <gsstark@mit.edu> writes:
You say it's "*very* busy" is it possible there are hundreds or thousands of
tuples in there that are uncommitted or committed after this query starts?
More specifically, I bet there's a huge number of completely empty
pages, which would be read by a seqscan but not an indexscan. VACUUM
FULL should fix it nicely, but it's odd that autovacuum isn't keeping
a lid on the file size. Maybe with so few live rows, it's confused into
thinking it doesn't need to vacuum the table often?
regards, tom lane
On Thu, 30 Sep 2004, Tom Lane wrote:
Greg Stark <gsstark@mit.edu> writes:
You say it's "*very* busy" is it possible there are hundreds or thousands of
tuples in there that are uncommitted or committed after this query starts?More specifically, I bet there's a huge number of completely empty
pages, which would be read by a seqscan but not an indexscan. VACUUM
FULL should fix it nicely, but it's odd that autovacuum isn't keeping
a lid on the file size. Maybe with so few live rows, it's confused into
thinking it doesn't need to vacuum the table often?
in the last hour or so:
[2004-09-30 03:41:18 PM] Performing: ANALYZE "public"."shown"
[2004-09-30 03:59:50 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 04:10:27 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 04:21:36 PM] Performing: ANALYZE "public"."shown"
[2004-09-30 04:27:05 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 04:32:17 PM] Performing: ANALYZE "public"."shown"
[2004-09-30 04:37:50 PM] Performing: VACUUM ANALYZE "public"."shown"
[2004-09-30 04:49:05 PM] Performing: VACUUM ANALYZE "public"."shown"
database directory itself is:
db# du 17144
28696 17144
after a vacuum full:
du 17144
6530 17144
Based on the following, I don't think that I need to raise my fsm settings
enough to make much of a difference ... or am I reading it wrong?
INFO: free space map: 674 relations, 9298 pages stored; 21360 total pages needed
DETAIL: Allocated FSM size: 1000 relations + 20000 pages = 178 kB shared memory.
Running with the index now results in:
Limit (cost=4.85..6.57 rows=1 width=50) (actual time=3.370..3.376 rows=1
loops=1)
InitPlan
-> Aggregate (cost=3.43..3.43 rows=1 width=8) (actual
time=2.562..2.567 rows=1 loops=1)
-> Hash Join (cost=1.57..3.35 rows=29 width=8) (actual
time=1.739..2.338 rows=27 loops=1)
Hash Cond: ("outer".banner_id = "inner".banner_id)
-> Seq Scan on shown s (cost=0.00..1.33 rows=33
width=12) (actual time=0.011..0.309 rows=33 loops=1)
-> Hash (cost=1.50..1.50 rows=29 width=4) (actual
time=0.589..0.589 rows=0 loops=1)
-> Seq Scan on banner b (cost=0.00..1.50 rows=29
width=4) (actual time=0.122..0.399 rows=27 loops=1)
Filter: ((end_date >= now()) OR (end_date IS
NULL))
-> Hash Join (cost=1.42..3.14 rows=1 width=50) (actual
time=3.355..3.355 rows=1 loops=1)
Hash Cond: ("outer".banner_id = "inner".banner_id)
-> Seq Scan on banner b (cost=0.00..1.66 rows=10 width=50)
(actual time=0.030..0.151 rows=16 loops=1)
Filter: ((start_date <= now()) AND ((end_date >= now()) OR
(end_date IS NULL)))
-> Hash (cost=1.41..1.41 rows=3 width=4) (actual
time=2.800..2.800 rows=0 loops=1)
-> Seq Scan on shown s (cost=0.00..1.41 rows=3 width=4)
(actual time=2.684..2.735 rows=6 loops=1)
Filter: (counter = $0)
Total runtime: 3.913 ms
(17 rows)
and without:
Limit (cost=4.85..6.57 rows=1 width=50) (actual time=2.111..2.116 rows=1
loops=1)
InitPlan
-> Aggregate (cost=3.43..3.43 rows=1 width=8) (actual
time=1.430..1.435 rows=1 loops=1)
-> Hash Join (cost=1.57..3.35 rows=29 width=8) (actual
time=0.676..1.236 rows=27 loops=1)
Hash Cond: ("outer".banner_id = "inner".banner_id)
-> Seq Scan on shown s (cost=0.00..1.33 rows=33
width=12) (actual time=0.007..0.290 rows=33 loops=1)
-> Hash (cost=1.50..1.50 rows=29 width=4) (actual
time=0.422..0.422 rows=0 loops=1)
-> Seq Scan on banner b (cost=0.00..1.50 rows=29
width=4) (actual time=0.025..0.246 rows=27 loops=1)
Filter: ((end_date >= now()) OR (end_date IS
NULL))
-> Hash Join (cost=1.42..3.14 rows=1 width=50) (actual
time=2.098..2.098 rows=1 loops=1)
Hash Cond: ("outer".banner_id = "inner".banner_id)
-> Seq Scan on banner b (cost=0.00..1.66 rows=10 width=50)
(actual time=0.024..0.225 rows=25 loops=1)
Filter: ((start_date <= now()) AND ((end_date >= now()) OR
(end_date IS NULL)))
-> Hash (cost=1.41..1.41 rows=3 width=4) (actual
time=1.562..1.562 rows=0 loops=1)
-> Seq Scan on shown s (cost=0.00..1.41 rows=3 width=4)
(actual time=1.517..1.537 rows=1 loops=1)
Filter: (counter = $0)
Total runtime: 2.393 ms
(17 rows)
so now we're in the same ball park, at least ...
I'll keep an eye on things to see if pg_autovacuum can 'keep up' without
having to re-add the index ...
----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664
Greg Stark wrote:
"Marc G. Fournier" <scrappy@postgresql.org> writes:
Its a *very* busy table ... and running on a 7.4.0 database ...
I wonder how many tuples are really in this table. Almost all of the 190ms is
spent in the two sequential scans of it. Which is an awful lot of time for a
32 tuple table.You say it's "*very* busy" is it possible there are hundreds or thousands of
tuples in there that are uncommitted or committed after this query starts?Alternatively, try a "vacuum full". If that helps then autovacuum is having
trouble keeping up with the rate of creation of dead tuples. You would have to
increase the FSM parameters.
There are scenarios where pg_autovacuum does have trouble keeping up.
The answer is to set more aggressive autovacuum thresholds.
Unfortunately the version of pg_autovacuum in contrib doens't support
table specific thresholds so you would have to set these cluster wide
which you may or may not want to do.
Alternatively you can keep the settings as is and have cron do a daily
vacuum full on that table.
Presumably autovacuum has warnings when it detects that scenario?
Unfortunately not. pg_autovacuum is pretty simple.
Tom Lane wrote:
Greg Stark <gsstark@mit.edu> writes:
You say it's "*very* busy" is it possible there are hundreds or thousands of
tuples in there that are uncommitted or committed after this query starts?More specifically, I bet there's a huge number of completely empty
pages, which would be read by a seqscan but not an indexscan. VACUUM
FULL should fix it nicely, but it's odd that autovacuum isn't keeping
a lid on the file size. Maybe with so few live rows, it's confused into
thinking it doesn't need to vacuum the table often?
I think autovacuum is keeping a lid on the file size, but the lid is too
loose. The default values for autovacuum were intentionally set a
little conservative so that it wouldn't cause a net slowdown by
vacuuming too often. Given that, for a 31 row table, the default
autovacuum settings say to vacuum every 1062 updates (or deletes),
depending on the size of the tuples that could be a lot of dead space.
Also, the default sleep time is 5 minutes, given your logs, autovacuum
feels the need to do something to your table every time it wakes up so I
think you are pushing the envelope.
Are you using default values for autovacuum? Could you prove a little
more detail by setting pg_autovacuum debug with -d 2
Matthew
On Thu, 30 Sep 2004, Matthew T. O'Connor wrote:
Are you using default values for autovacuum? Could you prove a little
more detail by setting pg_autovacuum debug with -d 2
Sure ... just restarted it with that setup ... btw ... I'm using -L for
logging ... what is the usual way of gettin git to go to syslog? I don't
mind the extra debugging level, but would like to be able to auto-rotate
the log :)
----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664
BTW, seems to be holding up pretty well so far, but I've also reduced, by
half, the baner ads on archives, so its not being hit near as much as it
used to be ...
du 17144
6562 17144
On Thu, 30 Sep 2004, Matthew T. O'Connor wrote:
Tom Lane wrote:
Greg Stark <gsstark@mit.edu> writes:
You say it's "*very* busy" is it possible there are hundreds or thousands
of
tuples in there that are uncommitted or committed after this query starts?More specifically, I bet there's a huge number of completely empty
pages, which would be read by a seqscan but not an indexscan. VACUUM
FULL should fix it nicely, but it's odd that autovacuum isn't keeping
a lid on the file size. Maybe with so few live rows, it's confused into
thinking it doesn't need to vacuum the table often?I think autovacuum is keeping a lid on the file size, but the lid is too
loose. The default values for autovacuum were intentionally set a little
conservative so that it wouldn't cause a net slowdown by vacuuming too often.
Given that, for a 31 row table, the default autovacuum settings say to vacuum
every 1062 updates (or deletes), depending on the size of the tuples that
could be a lot of dead space. Also, the default sleep time is 5 minutes,
given your logs, autovacuum feels the need to do something to your table
every time it wakes up so I think you are pushing the envelope.Are you using default values for autovacuum? Could you prove a little more
detail by setting pg_autovacuum debug with -d 2Matthew
---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
(send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664
Marc G. Fournier wrote:
On Thu, 30 Sep 2004, Matthew T. O'Connor wrote:
Are you using default values for autovacuum? Could you prove a
little more detail by setting pg_autovacuum debug with -d 2Sure ... just restarted it with that setup ... btw ... I'm using -L
for logging ... what is the usual way of gettin git to go to syslog?
I don't mind the extra debugging level, but would like to be able to
auto-rotate the log :)
There is no "normal" way to get it to go to syslog. The version of
autovacuum that didn't make the 8.0 cut had support for it. I'm sorry
to say that since I tried and failed to integrate autovacuum into the
backend, that the 8.0 autovacuum in contrib is exactly the same as the
7.4.3 version :-(
I'm not sure but I think someone a while ago posted a patch that added
syslog support to pg_autovacuum.
Matthew
On Fri, 1 Oct 2004, Matthew T. O'Connor wrote:
Marc G. Fournier wrote:
On Thu, 30 Sep 2004, Matthew T. O'Connor wrote:
Are you using default values for autovacuum? Could you prove a little
more detail by setting pg_autovacuum debug with -d 2Sure ... just restarted it with that setup ... btw ... I'm using -L for
logging ... what is the usual way of gettin git to go to syslog? I don't
mind the extra debugging level, but would like to be able to auto-rotate
the log :)There is no "normal" way to get it to go to syslog. The version of
autovacuum that didn't make the 8.0 cut had support for it. I'm sorry to say
that since I tried and failed to integrate autovacuum into the backend, that
the 8.0 autovacuum in contrib is exactly the same as the 7.4.3 version :-(I'm not sure but I think someone a while ago posted a patch that added syslog
support to pg_autovacuum.
Nope, that's cool ... using the -L function works for my purposes :)
Thanks ...
----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org Yahoo!: yscrappy ICQ: 7615664