
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

Thu, 30 Sep 2004 15:03:58 -0300 (ADT)
"Marc G. Fournier" <scrappy@postgresql.org>
CREATE INDEX speeds up query on 31 row table ...
"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


30 Sep 2004 14:30:13 -0400
Greg Stark <gsstark@mit.edu>
Re: CREATE INDEX speeds up query on 31 row table ...
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

Thu, 30 Sep 2004 14:56:48 -0400
Tom Lane <tgl@sss.pgh.pa.us>
Re: CREATE INDEX speeds up query on 31 row table ... 
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

Thu, 30 Sep 2004 16:57:16 -0300 (ADT)
"Marc G. Fournier" <scrappy@postgresql.org>
Re: CREATE INDEX speeds up query on 31 row table ... 
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.


Thu, 30 Sep 2004 16:29:23 -0400
"Matthew T. O'Connor" <matthew@zeut.net>
Re: CREATE INDEX speeds up query on 31 row table ...
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


Thu, 30 Sep 2004 16:42:10 -0400
"Matthew T. O'Connor" <matthew@zeut.net>
Re: CREATE INDEX speeds up query on 31 row table ...
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

Thu, 30 Sep 2004 20:03:14 -0300 (ADT)
"Marc G. Fournier" <scrappy@postgresql.org>
Re: CREATE INDEX speeds up query on 31 row table ...

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 2
>
> Matthew
>
>
> ---------------------------(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

Thu, 30 Sep 2004 20:04:30 -0300 (ADT)
"Marc G. Fournier" <scrappy@postgresql.org>
Re: CREATE INDEX speeds up query on 31 row table ...
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 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 :)
>
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


Fri, 01 Oct 2004 00:33:28 -0400
"Matthew T. O'Connor" <matthew@zeut.net>
Re: CREATE INDEX speeds up query on 31 row table ...
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 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 :)
>> 
> 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

Fri, 1 Oct 2004 10:09:40 -0300 (ADT)
"Marc G. Fournier" <scrappy@postgresql.org>
Re: CREATE INDEX speeds up query on 31 row table ...