300 seconds in less than 1 second with pg_autovacuum

"Harald Massa" <[email protected]>
Newsgroups gmane.comp.db.postgresql.devel.win32
Message-ID <[email protected]> 
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



---------------------------(end of broadcast)---------------------------
TIP 8: explain analyze is your friend
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.