Re: BUG #5200: Use of min suffix in autovacuum_naptime ignored

(Please keep the list CC'd so that others can help)

Autovacuum_naptime is the minimum delay between autovacuum runs *on any
given database*, so what you're seeing is normal.

A.J.Masterton wrote:
> The relevant lines from the config file are below. In this exmple the autovacuum_naptime is set to 1min which is the default.
>
> #------------------------------------------------------------------------------
> # AUTOVACUUM PARAMETERS
> #------------------------------------------------------------------------------
>
> autovacuum = on # Enable autovacuum subprocess? 'on'
> # requires track_counts to also be on.
> log_autovacuum_min_duration = 0 # -1 disables, 0 logs all actions and
> # their durations, > 0 logs only
> # actions running at least that time.
> autovacuum_max_workers = 3 # max number of autovacuum subprocesses
> autovacuum_naptime = 1min # time between autovacuum runs
> autovacuum_vacuum_threshold = 50 # min number of row updates before
> # vacuum
> autovacuum_analyze_threshold = 50 # min number of row updates before
> # analyze
> autovacuum_vacuum_scale_factor = 0.2 # fraction of table size before vacuum
> autovacuum_analyze_scale_factor = 0.1 # fraction of table size before analyze
> autovacuum_freeze_max_age = 200000000 # maximum XID age before forced vacuum
> # (change requires restart)
> autovacuum_vacuum_cost_delay = 20 # default vacuum cost delay for
> # autovacuum, -1 means use
> # vacuum_cost_delay
> autovacuum_vacuum_cost_limit = -1 # default vacuum cost limit for
> # autovacuum, -1 means use
> # vacuum_cost_limit
>
> Below is a set of postgres log lines with the setting above and log_min_messages = debug2:
>
> 2009-11-20 22:11:23 GMT LOG: database system was shut down at 2009-11-20 22:11:21 GMT
> 2009-11-20 22:11:23 GMT DEBUG: checkpoint record is at 5/EB18D080
> 2009-11-20 22:11:23 GMT DEBUG: redo record is at 5/EB18D080; shutdown TRUE
> 2009-11-20 22:11:23 GMT DEBUG: next transaction ID: 0/2909382; next OID: 2761814
> 2009-11-20 22:11:23 GMT DEBUG: next MultiXactId: 1; next MultiXactOffset: 0
> 2009-11-20 22:11:23 GMT DEBUG: transaction ID wrap limit is 2147484025, limited by database "sdd-demo"
> 2009-11-20 22:11:23 GMT LOG: autovacuum launcher started
> 2009-11-20 22:11:23 GMT LOG: database system is ready to accept connections
> 2009-11-20 22:11:24 GMT DEBUG: autovacuum: processing database "abc1"
> 2009-11-20 22:11:24 GMT DEBUG: server process (PID 22183) exited with exit code 0
> 2009-11-20 22:11:25 GMT DEBUG: autovacuum: processing database "abc2"
> 2009-11-20 22:11:25 GMT DEBUG: server process (PID 22187) exited with exit code 0
> 2009-11-20 22:11:26 GMT DEBUG: autovacuum: processing database "abc3"
> 2009-11-20 22:11:26 GMT DEBUG: server process (PID 22188) exited with exit code 0
> 2009-11-20 22:11:27 GMT DEBUG: autovacuum: processing database "test_mso"
> 2009-11-20 22:11:27 GMT DEBUG: server process (PID 22189) exited with exit code 0
> 2009-11-20 22:11:28 GMT DEBUG: autovacuum: processing database "template1"
> 2009-11-20 22:11:28 GMT DEBUG: server process (PID 22190) exited with exit code 0
> 2009-11-20 22:11:29 GMT DEBUG: autovacuum: processing database "abc4"
> 2009-11-20 22:11:29 GMT DEBUG: server process (PID 22191) exited with exit code 0
> 2009-11-20 22:11:29 GMT DEBUG: autovacuum: processing database "abc5"
> 2009-11-20 22:11:29 GMT DEBUG: server process (PID 22192) exited with exit code 0
> 2009-11-20 22:11:30 GMT DEBUG: autovacuum: processing database "abc6"
> 2009-11-20 22:11:30 GMT DEBUG: server process (PID 22193) exited with exit code 0
> 2009-11-20 22:11:31 GMT DEBUG: autovacuum: processing database "abc7"
> 2009-11-20 22:11:31 GMT DEBUG: server process (PID 22194) exited with exit code 0
> 2009-11-20 22:11:32 GMT DEBUG: autovacuum: processing database "sdd-live"
> 2009-11-20 22:11:32 GMT DEBUG: server process (PID 22195) exited with exit code 0
> 2009-11-20 22:11:33 GMT DEBUG: autovacuum: processing database "abc8"
> 2009-11-20 22:11:33 GMT DEBUG: server process (PID 22196) exited with exit code 0
> 2009-11-20 22:11:34 GMT DEBUG: autovacuum: processing database "abc9"
> 2009-11-20 22:11:34 GMT DEBUG: server process (PID 22197) exited with exit code 0
>
> As you can see the autovacuum process appears to be running every second.
>
> If I set the autovacuum_naptime = 60min the log output is below:
>
> 2009-11-20 22:18:07 GMT LOG: database system was shut down at 2009-11-20 22:15:17 GMT
> 2009-11-20 22:18:07 GMT DEBUG: checkpoint record is at 5/EB18D0C8
> 2009-11-20 22:18:07 GMT DEBUG: redo record is at 5/EB18D0C8; shutdown TRUE
> 2009-11-20 22:18:07 GMT DEBUG: next transaction ID: 0/2909382; next OID: 2761814
> 2009-11-20 22:18:07 GMT DEBUG: next MultiXactId: 1; next MultiXactOffset: 0
> 2009-11-20 22:18:07 GMT DEBUG: transaction ID wrap limit is 2147484025, limited by database "sdd-demo"
> 2009-11-20 22:18:07 GMT LOG: database system is ready to accept connections
> 2009-11-20 22:18:07 GMT LOG: autovacuum launcher started
> 2009-11-20 22:18:58 GMT DEBUG: autovacuum: processing database "abc1"
> 2009-11-20 22:18:58 GMT DEBUG: server process (PID 22776) exited with exit code 0
> 2009-11-20 22:19:50 GMT DEBUG: autovacuum: processing database "abc2"
> 2009-11-20 22:19:50 GMT DEBUG: server process (PID 22789) exited with exit code 0
> 2009-11-20 22:20:41 GMT DEBUG: autovacuum: processing database "abc3"
> 2009-11-20 22:20:41 GMT DEBUG: server process (PID 22804) exited with exit code 0
> 2009-11-20 22:21:32 GMT DEBUG: autovacuum: processing database "test_mso"
> 2009-11-20 22:21:32 GMT DEBUG: server process (PID 22839) exited with exit code 0
> 2009-11-20 22:22:24 GMT DEBUG: autovacuum: processing database "template1"
> 2009-11-20 22:22:24 GMT DEBUG: server process (PID 22859) exited with exit code 0
>
> As you can see the autovacuum process is now running almost every minute (appears to be every ~52 secs)
>
> The installed postgres RPMs are the PGDG ons from the yum repository and the details are below:
>
> postgresql-libs-8.3.8-1PGDG.rhel5.x86_64.rpm
> postgresql-8.3.8-1PGDG.rhel5.x86_64.rpm
> postgresql-server-8.3.8-1PGDG.rhel5.x86_64.rpm
>
> Not sure what else info I maybe able to give, but if there is anything more I can help with let me know.
>
> -Andrew
>
> ________________________________________
> From: Heikki Linnakangas [heikki(dot)linnakangas(at)enterprisedb(dot)com]
> Sent: 20 November 2009 19:51
> To: Andrew Masterton
> Cc: pgsql-bugs(at)postgresql(dot)org
> Subject: Re: [BUGS] BUG #5200: Use of min suffix in autovacuum_naptime ignored
>
> Andrew Masterton wrote:
>> The following bug has been logged online:
>>
>> Bug reference: 5200
>> Logged by: Andrew Masterton
>> Email address: a(dot)j(dot)masterton(at)open(dot)ac(dot)uk
>> PostgreSQL version: 8.3.8
>> Operating system: RedHat Enterprise 5.4
>> Description: Use of min suffix in autovacuum_naptime ignored
>> Details:
>>
>> The default configuration of 8.3.8 has autovacuum_naptime = 1min. It would
>> appear that the min is ignored as turning up debug show the autovacuum
>> running every second. On my 8.3.8 installation with a large number of
>> databases and tables this has the side effect of the stats collector process
>> using up large amounts of CPU and I/O.
>>
>> Changing this setting to 60min causes the autovacuum process to have the
>> correct 60 second naptime.
>>
>> I Haven't tried removing the min and setting it to s to see if any time
>> suffix is ignored for this configuration option.
>
> I can't reproduce this. Can you send the relevant lines from your
> postgresql.conf and the logs showing what's happening, and/or anything
> else that might help to track that down?
>
> --
> Heikki Linnakangas
> EnterpriseDB http://www.enterprisedb.com
>
>
> The Open University is incorporated by Royal Charter (RC 000391), an exempt charity in England & Wales and a charity registered in Scotland (SC 038302).

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com