Re: [Postgresql 8.2.3] autovacuum starting up even after disabling ?

Hey all,

Iam using PostgreSQL 8.2.3 on RHEL4 (Linux 2.6.20.3-custom #4 SMP x86_64 x86_64
x86_64 GNU/Linux).

I have autovacuum tunrned off in the config, but it still seems to start up once
everyday. What could be the cause of this ?

TIA
Dushyanth

$ psql -U postgres
postgres=# show autovacuum;
autovacuum
------------
off
(1 row)

$ grep autovacuum postgresql.conf

#autovacuum = off
#autovacuum_naptime = 60
#autovacuum_vacuum_threshold = 1000
#autovacuum_analyze_threshold = 500
#autovacuum_vacuum_scale_factor = 0.4
#autovacuum_analyze_scale_factor = 0.2
#autovacuum_vacuum_cost_delay = -1
#autovacuum_vacuum_cost_limit = -1

# autovacuum processes

postgres 16508 9.2 0.1 2310836 37984 ? Ds 09:58 0:09 \_ postgres:
autovacuum process db1
postgres 19626 7.2 0.0 2289524 27704 ? Ds 10:09 0:03 \_ postgres:
autovacuum process db1
postgres 20861 7.8 0.0 2298844 31028 ? Ds 10:13 0:08 \_ postgres:
autovacuum process db1
postgres 21673 6.1 0.1 2336904 33400 ? Ds 10:16 0:12 \_ postgres:
autovacuum process db1
postgres 21673 6.2 0.1 2339840 57400 ? Ds 10:16 0:31 \_ postgres:
autovacuum process db1
postgres 13597 11.6 0.0 2358352 29936 ? Ds 17:12 0:20 \_ postgres:
autovacuum process db2
postgres 13597 8.7 0.1 2358352 39056 ? Ds 17:12 0:41 \_ postgres:
autovacuum process db2
postgres 13597 7.8 0.1 2363924 45540 ? Ds 17:12 1:01 \_ postgres:
autovacuum process db2

On Friday 04 July 2008 7:51 am, Dushyanth wrote:
> Hey all,
>
> Iam using PostgreSQL 8.2.3 on RHEL4 (Linux 2.6.20.3-custom #4 SMP x86_64
> x86_64 x86_64 GNU/Linux).
>
> I have autovacuum tunrned off in the config, but it still seems to start up
> once everyday. What could be the cause of this ?
>
> TIA
> Dushyanth
>
>

From the docs:
http://www.postgresql.org/docs/8.3/interactive/runtime-config-autovacuum.html

autovacuum (boolean)

Controls whether the server should run the autovacuum launcher daemon.
This is on by default; however, track_counts must also be turned on for
autovacuum to work. This parameter can only be set in the postgresql.conf
file or on the server command line.

--> Note that even when this parameter is disabled, the system will launch
autovacuum processes if necessary to prevent transaction ID wraparound. See
Section 23.1.3 for more information.

--
Adrian Klaver
aklaver(at)comcast(dot)net

Dushyanth escribió:

> # autovacuum processes
>
> postgres 16508 9.2 0.1 2310836 37984 ? Ds 09:58 0:09 \_ postgres:
> autovacuum process db1
> postgres 19626 7.2 0.0 2289524 27704 ? Ds 10:09 0:03 \_ postgres:
> autovacuum process db1
> postgres 20861 7.8 0.0 2298844 31028 ? Ds 10:13 0:08 \_ postgres:
> autovacuum process db1
> postgres 21673 6.1 0.1 2336904 33400 ? Ds 10:16 0:12 \_ postgres:
> autovacuum process db1
> postgres 21673 6.2 0.1 2339840 57400 ? Ds 10:16 0:31 \_ postgres:
> autovacuum process db1
> postgres 13597 11.6 0.0 2358352 29936 ? Ds 17:12 0:20 \_ postgres:
> autovacuum process db2
> postgres 13597 8.7 0.1 2358352 39056 ? Ds 17:12 0:41 \_ postgres:
> autovacuum process db2
> postgres 13597 7.8 0.1 2363924 45540 ? Ds 17:12 1:01 \_ postgres:
> autovacuum process db2

Something is seriously wrong here -- there should be only one autovacuum
process ever in 8.2. Can you show a more complete ps tree, and perhaps
include PPID in the listing?

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Hey,

On Fri, Jul 4, 2008 at 10:56 PM, Adrian Klaver <aklaver(at)comcast(dot)net> wrote:

>
> Am forwarding back to list.
> One question? Did you do pg_ctl reload after changing the config file?

I did not change any config yet - autovacuum was always disabled since
the day PG was set up.

Thanks
Dushyanth

Hey,

>> # autovacuum processes
>>
>> postgres 16508 9.2 0.1 2310836 37984 ? Ds 09:58 0:09 \_ postgres:
>> autovacuum process db1
>> postgres 19626 7.2 0.0 2289524 27704 ? Ds 10:09 0:03 \_ postgres:
>> autovacuum process db1
>> postgres 20861 7.8 0.0 2298844 31028 ? Ds 10:13 0:08 \_ postgres:
>> autovacuum process db1
>> postgres 21673 6.1 0.1 2336904 33400 ? Ds 10:16 0:12 \_ postgres:
>> autovacuum process db1
>> postgres 21673 6.2 0.1 2339840 57400 ? Ds 10:16 0:31 \_ postgres:
>> autovacuum process db1
>> postgres 13597 11.6 0.0 2358352 29936 ? Ds 17:12 0:20 \_ postgres:
>> autovacuum process db2
>> postgres 13597 8.7 0.1 2358352 39056 ? Ds 17:12 0:41 \_ postgres:
>> autovacuum process db2
>> postgres 13597 7.8 0.1 2363924 45540 ? Ds 17:12 1:01 \_ postgres:
>> autovacuum process db2
>
> Something is seriously wrong here -- there should be only one autovacuum
> process ever in 8.2. Can you show a more complete ps tree, and perhaps
> include PPID in the listing?

My bad - I messed up the above. I grepped for autovacuum in my process
logs and included all matches.

There is only one autovacuum process when it starts up. Below is the
correct output from one of the logs

postgres 8951 0.0 0.1 2270284 60484 pts/0 S Jun29 0:36
/usr/local/postgres/pgsql-8.2.3/bin/postgres -D
/usr/local/postgres/current/data -i
postgres 8989 4.9 0.0 57496 948 ? Ss Jun29 282:33 \_
postgres: logger process
postgres 9002 0.0 6.4 2271532 2126852 ? Ss Jun29 2:13 \_
postgres: writer process
postgres 9003 0.0 0.0 58564 1024 ? Ss Jun29 0:01 \_
postgres: archiver process
postgres 9004 0.0 0.0 58448 832 ? Ss Jun29 0:00 \_
postgres: stats collector process
postgres 871 0.0 0.1 2274216 36200 ? Ss Jul02 0:00 \_
postgres: postgres dbname [local] idle
postgres 16508 9.2 0.1 2310836 37984 ? Ds 09:58 0:09 \_
postgres: autovacuum process dbname

Thanks
Dushyanth

dushy escribió:

> My bad - I messed up the above. I grepped for autovacuum in my process
> logs and included all matches.

Ah, ok -- that makes more sense.

> There is only one autovacuum process when it starts up. Below is the
> correct output from one of the logs

Good.

Do you have entries in the pg_autovacuum table in this database?

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Hey,

>> There is only one autovacuum process when it starts up. Below is the
>> correct output from one of the logs
>
> Good.
>
> Do you have entries in the pg_autovacuum table in this database?

No. Its empty.

TIA
Dushyanth

dushy <dushyanth(at)gmail(dot)com> writes:
> On Fri, Jul 4, 2008 at 10:56 PM, Adrian Klaver <aklaver(at)comcast(dot)net> wrote:
>> One question? Did you do pg_ctl reload after changing the config file?

> I did not change any config yet - autovacuum was always disabled since
> the day PG was set up.

A mistake here seems by far the most likely explanation. Does
"show autovacuum" confirm that it's off?

regards, tom lane

Hi,

Tom Lane <tgl <at> sss.pgh.pa.us> writes:
> dushy <dushyanth <at> gmail.com> writes:
> > On Fri, Jul 4, 2008 at 10:56 PM, Adrian Klaver <aklaver <at> comcast.net>
wrote:
> >> One question? Did you do pg_ctl reload after changing the config file?
>
> > I did not change any config yet - autovacuum was always disabled since
> > the day PG was set up.
>
> A mistake here seems by far the most likely explanation.

I have rechecked the config multiple times till now :)

> Does "show autovacuum" confirm that it's off?

Yes.

# show autovacuum;
autovacuum
------------
off
(1 row)

# Below pocess tree is from todays process logs (i just logged `ps fax` output
every 5 mts to a file)

postgres 8951 0.0 0.1 2270284 60484 ? S Jun29 0:53
/usr/local/postgres/pgsql-8.2.3/bin/postgres -D /usr/local/p
ostgres/current/data -i
postgres 8989 4.8 0.0 57496 948 ? Ss Jun29 547:03 \_ postgres:
logger process
postgres 9002 0.0 6.4 2271532 2127764 ? Ss Jun29 4:06 \_ postgres:
writer process
postgres 9003 0.0 0.0 58564 1024 ? Ss Jun29 0:02 \_ postgres:
archiver process
postgres 9004 0.0 0.0 58448 832 ? Ss Jun29 0:00 \_ postgres:
stats collector process
postgres 10259 3.7 3.4 2293908 1143908 ? Ds 07:06 3:18 \_ postgres:
autovacuum process dbname

# complete postgresql.conf

listen_addresses = '*'
port = 5432
max_connections = 1200
superuser_reserved_connections = 5
shared_buffers = 262143
work_mem = 49152
max_fsm_pages = 6000000
checkpoint_segments = 9
archive_command = '/usr/local/postgres/WALLogs/copy_to_archive.sh %p %f'
effective_cache_size = 2752512
random_page_cost = 2.5
default_statistics_target = 50
log_destination = 'stderr'
redirect_stderr = true
log_directory = 'pg_log'
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_rotation_size = 256000
log_connections = on
log_disconnections = on
log_duration = on
log_line_prefix = '%t [%p]: [%l-1] '
log_statement = 'all'
stats_start_collector = on
stats_command_string = on
statement_timeout = 120000
deadlock_timeout = 1000
add_missing_from = on

Dushyanth <dushyanth(at)gmail(dot)com> writes:
>> Does "show autovacuum" confirm that it's off?

> Yes.

> # show autovacuum;
> autovacuum
> ------------
> off
> (1 row)

Then the only other possibility is that autovacuum is being launched to
prevent XID wraparound. Are there any tables in that database with
particularly old relfrozenxid? Try something like

select relname, age(relfrozenxid) from pg_class
where relkind in ( 'r', 't') order by 2 desc;

regards, tom lane

Hey,

> Tom Lane <tgl <at> sss.pgh.pa.us> writes:
> > Dushyanth <dushyanth <at> gmail.com> writes:
> >> Does "show autovacuum" confirm that it's off?
>
> > Yes.
>
> > # show autovacuum;
> > autovacuum
> > ------------
> > off
> > (1 row)
>
> Then the only other possibility is that autovacuum is being launched to
> prevent XID wraparound. Are there any tables in that database with
> particularly old relfrozenxid? Try something like
>
> select relname, age(relfrozenxid) from pg_class
> where relkind in ( 'r', 't') order by 2 desc;

Below are the unique age(relfrozenxid) values that i see from the above query

# psql -U postgres -d dbname -c "select relname, age(relfrozenxid) from pg_class
where relkind in ( 'r', 't') order by 2 desc;" | awk '{print $3}' | sort | uniq

140835139
150945753
185741480

They are all under 200 million - Also please refer to
http://archives.postgresql.org/pgsql-general/2008-07/msg00195.php. I have
provided more details in here.

Thanks
Dushyanth

Dushyanth escribió:

> Below are the unique age(relfrozenxid) values that i see from the above query
>
> # psql -U postgres -d dbname -c "select relname, age(relfrozenxid) from pg_class
> where relkind in ( 'r', 't') order by 2 desc;" | awk '{print $3}' | sort | uniq
>
> 140835139
> 150945753
> 185741480
>
> They are all under 200 million

Weird :-(

Could you fetch from pg_stat_activity the table it's processing, and its
pg_class row and that of its toast table (if any)?

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Dushyanth <dushyanth(at)gmail(dot)com> writes:
>> Tom Lane <tgl <at> sss.pgh.pa.us> writes:
>> Then the only other possibility is that autovacuum is being launched to
>> prevent XID wraparound. Are there any tables in that database with
>> particularly old relfrozenxid?

> Below are the unique age(relfrozenxid) values that i see from the above query

> 140835139
> 150945753
> 185741480

Hmph. Does pg_database.datfrozenxid agree with that?

regards, tom lane

Hi,

Tom Lane <tgl <at> sss.pgh.pa.us> writes:
> Dushyanth <dushyanth <at> gmail.com> writes:
> >> Tom Lane <tgl <at> sss.pgh.pa.us> writes:
> >> Then the only other possibility is that autovacuum is being launched to
> >> prevent XID wraparound. Are there any tables in that database with
> >> particularly old relfrozenxid?
>
> > Below are the unique age(relfrozenxid) values that i see from the above query
>
> > 140835139
> > 150945753
> > 185741480
>
> Hmph. Does pg_database.datfrozenxid agree with that?

Yes.

/usr/local/postgres/current/bin/psql -t -U postgres -d template1 -c"SELECT
datname, age(datfrozenxid) FROM pg_database;"
postgres | 169111100
db1 | 169288969
db2 | 192179807
template1 | 153877757
template0 | 195372755

autovacuum seems to run on db1 and db2. Iam attempting to get the table details
as Alvaro requested

On a side note, i see connections in '<IDLE> in transaction' state. Can this
cause such behaviour ?

TIA
Dushyanth

Hey,

> > They are all under 200 million
>
> Weird
>
> Could you fetch from pg_stat_activity the table it's processing, and its
> pg_class row and that of its toast table (if any)?

Sorry for the delay. Required details are at
http://pastebin.com/pastebin.php?dl=fd699fbb

Let me know if you need anything else.

TIA
Dushyanth

Hi Tom & Alvaro,

> Hey,
>
> > > They are all under 200 million
> >
> > Weird
> >
> > Could you fetch from pg_stat_activity the table it's processing, and its
> > pg_class row and that of its toast table (if any)?
>
> Sorry for the delay. Required details are at
> http://pastebin.com/pastebin.php?dl=fd699fbb

Did you guys have a chance to look at this ? I scheduled a VACUUM ANALYZE
VERBOSE on all databases to run daily and this has been running since few weeks
now.

Also note that the vacuum on my primary database is run like below to avoid
statement timeouts (set to 120000 in postgresql.conf).

> vacuum.sql
SET STATEMENT_TIMEOUT TO 0;
VACUUM ANALYSE verbose;

psql -U postgres -d dbname -f /path/to/vacuum.sql

For other databases, i do 'vacuumdb -zv dbname' .

The vacuum logs and the pgfouine vacuum reports dont show anything funny.

Autovacuum still starts up though. This process started on 09-08-2008 11.40 GMT
and ran till 10-08-2008 08:00 GMT. It also seems to be touching few other tables
apart from the tables i posted last about.

postgres 30430 0.0 0.1 2270284 60500 ? S Jul24 2:15
/usr/local/postgres/pgsql-8.2.3/bin/postgres -D
/usr/local/postgres/current/foundationdata -i
postgres 30437 5.0 0.0 57380 760 ? Ds Jul24 1196:04 \_ postgres:
logger process
postgres 31907 0.0 6.4 2271528 2129736 ? Ss Jul24 8:48 \_ postgres:
writer process
postgres 31908 0.0 0.0 58448 844 ? Ss Jul24 0:06 \_ postgres:
archiver process
postgres 31909 0.0 0.0 58448 812 ? Ss Jul24 0:00 \_ postgres:
stats collector process
postgres 7112 1.8 1.7 2291200 570796 ? Ss 11:40 0:05 \_ postgres:
autovacuum process foundation

I don't know what autovacuum is panicking about to warrant a force run.

Any pointers ?

TIA
Dushyanth