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.linnakangas@enterprisedb.com]
> Sent: 20 November 2009 19:51
> To: Andrew Masterton
> Cc: pgsql-bugs@postgresql.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.j.masterton@open.ac.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
registeredin Scotland (SC 038302). 


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