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.

Search Discussions

  • Heikki Linnakangas at Nov 20, 2009 at 7:51 pm

    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
  • Heikki Linnakangas at Nov 21, 2009 at 3:08 pm
    (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 registered in Scotland (SC 038302).

    --
    Heikki Linnakangas
    EnterpriseDB http://www.enterprisedb.com
  • A.J.Masterton at Nov 21, 2009 at 4:06 pm
    Sorry force of habit with the CC.

    Sorry a bit of confusion here with the documentations meaing.

    Does the autovacuum_naptime also then mean that the daemon will wil try to scan all databases within system in the autovacuum_naptime?
    Therefore as the number of databases increases the amount of work the autovacuum daemon has to do in the autovacuum_naptime interval increases?
    Is that why with the setting set to 1min it scans a new database every second yet with it set to 60min it spaces out the vacuums to make sure it gets through them all in 60min?

    Finally do people think it could be better to have some sort of configuration option to allow spacing between autovacuum runs across the whole system? This would stop the heavy statistics gatherer load I see with the current way autovacuum works when there are a large number of databases? (sorry for all the questions)

    Maybe something like a scale factor as there are for other autovacuum options...

    (Sorry again if i've got the way it all works wrong...)

    -Andrew
    ________________________________________
    From: Heikki Linnakangas [heikki.linnakangas@enterprisedb.com]
    Sent: 21 November 2009 15:08
    To: A.J.Masterton
    Cc: PostgreSQL Bugs
    Subject: Re: [BUGS] 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 registered in Scotland (SC 038302).

    --
    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).

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-bugs @
categoriespostgresql
postedNov 19, '09 at 9:09p
activeNov 21, '09 at 4:06p
posts4
users2
websitepostgresql.org
irc#postgresql

People

Translate

site design / logo © 2021 Grokbase