300 seconds in less than 1 second with pg_autovacuum

From: "Harald Massa" <ghum(at)gmx(dot)net>
To: pgsql-hackers-win32(at)postgresql(dot)org
Subject: 300 seconds in less than 1 second with pg_autovacuum
Date: 2005-01-21 12:54:56
Message-ID: 16265.1106312096@www40.gmx.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers-win32

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

Responses

Browse pgsql-hackers-win32 by date

  From Date Subject
Next Message Harald Massa 2005-01-21 13:02:22 Re: 300 seconds in less than 1 second with pg_autovacuum
Previous Message Magnus Hagander 2005-01-21 11:46:32 Re: [PATCHES] pg_autovacuum fails to start - 8.0 Release