300 seconds in less than 1 second with pg_autovacuum

With all the patches from Dave I finally made pg_autovacuum run.
And it runs, and runs ... quicker than I want it to. Some extract from my
logfile:

[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:    Printing
command_args
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->host=(null)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->port=(null)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->username=postgres
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->password=SuperSuperSuperSecret
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->logfile=c:\ghum\data\pg_log\autovacuum.log
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->install_as_service=0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->remove_as_service=0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->service_dependencies=(null)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->service_user=(null)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->service_password=(null)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->sleep_base_value=300
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->sleep_scaling_factor=2.000000
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->vacuum_base_threshold=1000
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->vacuum_scaling_factor=2.000000
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->analyze_base_threshold=500
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->analyze_scaling_factor=1.000000
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->av_vacuum_cost_delay=(default)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->av_vacuum_cost_page_hit=(default)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->av_vacuum_cost_page_miss=(default)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->av_vacuum_cost_page_dirty=(default)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
args->av_vacuum_cost_limit=(default)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      args->debug=4
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:    pg_autovacuum
starting in Windows Service mode
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   select
oid,age(datfrozenxid) from pg_database where datname = 'template1'
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:    dbname: template1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      oid: 1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      username:
postgres
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      password:
faghimwyo
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      conn is valid,
(connected)
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
default_analyze_threshold: 1000
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
default_vacuum_threshold: 500
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   SHOW
stats_row_level
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   updating the
database list
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   select
oid,datname,age(datfrozenxid) from pg_database where datname!='template0'
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   added database:
jds
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   added database:
handbuch
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:    dbname: template1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      oid: 1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      username:
postgres
[....... lots of lines for every table ....]
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   added table:
jds."public"."formularfeld"
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      table name:
jds."pg_catalog"."pg_database"
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:         relid: 1262;
 relisshared: 1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:         reltuples:
3.000000;  relpages: 1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
curr_analyze_count: 0; curr_vacuum_count: 0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
last_analyze_count: 0; last_vacuum_count: 0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
analyze_threshold: 503; vacuum_threshold: 1006
[2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG:   added table:
jds."pg_catalog"."pg_database"
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:      table name:
jds."public"."dbmodis"
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:         relid: 17325;
  relisshared: 0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:         reltuples:
16.000000;  relpages: 1
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
curr_analyze_count: 0; curr_vacuum_count: 0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
last_analyze_count: 0; last_vacuum_count: 0
[2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO:
analyze_threshold: 516; vacuum_threshold: 1032
[... many more similar lines ...]
[2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO:      table name:
handbuch."public"."hbart"
[2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO:         relid: 97071;
  relisshared: 0
[2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO:         reltuples:
0.000000;  relpages: 0
[2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO:
curr_analyze_count: 28; curr_vacuum_count: 21
[2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO:
last_analyze_count: 28; last_vacuum_count: 21
[2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO:
analyze_threshold: 500; vacuum_threshold: 1000
[2005-01-21 13:41:52 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:52 Westeuropäische Normalzeit] DEBUG:   3 All DBs checked
in: 250000 usec, will sleep for 300 secs.

now... 1 second passes ....

[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   4 All DBs checked
in: 156000 usec, will sleep for 300 secs.

that was quick ... and 300 secs. will pass before 1 second is over....

[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   updating the
database list
[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   select
oid,datname,age(datfrozenxid) from pg_database where datname!='template0'
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:    dbname: template1
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      oid: 1
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      username:
postgres
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      password:
xxxxxxxxx
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      conn is valid,
(connected)
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:
default_analyze_threshold: 1000
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:
default_vacuum_threshold: 500
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:    dbname: jds
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      oid: 17254
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      username:
postgres
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      password:
xxxxxxxx
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      conn is null,
(not connected)
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:
default_analyze_threshold: 1000
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:
default_vacuum_threshold: 500
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:    dbname: handbuch
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      oid: 96986
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      username:
postgres
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      password:
faghimwyo
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:      conn is null,
(not connected)
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:
default_analyze_threshold: 1000
[2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO:
default_vacuum_threshold: 500
[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[ ..... lots of similiar lines ....]
[2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG:   5 All DBs checked
in: 266000 usec, will sleep for 300 secs.
[2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG:   6 All DBs checked
in: 140000 usec, will sleep for 300 secs.
[2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG:   updating the
database list

[2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG:   7 All DBs checked
in: 234000 usec, will sleep for 300 secs.
[2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG:   8 All DBs checked
in: 156000 usec, will sleep for 300 secs.

again... 300 secs pass in one second....

                                               ] DEBUG:   9 All DBs checked
in: 250000 usec, will sleep for 300 secs.
[2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG:   select
a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del
from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind =
'r'
[2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG:   10 All DBs checked
in: 140000 usec, will sleep for 300 secs.
[2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG:   updating the
database list

[.... yeah, I know, time passes fast when you are in love or having fun.
But... that is WAY TO FAST for 300secs, isn't it??? ...]

[2005-01-21 13:42:42 Westeuropäische Normalzeit] DEBUG:   39 All DBs checked
in: 235000 usec, will sleep for 300 secs.
[2005-01-21 13:42:42 Westeuropäische Normalzeit] INFO:    pg_autovacuum
service stopping...


That said, my logfile with -d 4 went up to 4 Gig in no time at all ... bad
idea of me trying to open it within an editor :))) (read it as 4 Meg)

What is going wrong? I did not fiddle with the "Sleep-Period", just left it
on default.

(this error happens with pg_autovacuum from 8.0 Release and with the second
patch Dave sent me via email)

Harald