On Fri, Apr 16, 2010 at 11:41 AM, Tom Lane <[email protected]> wrote:
> Wow. Well, we have a smoking gun here: for some reason, autovacuum
> isn't running, or isn't doing its job if it is. If it's not running
> at all, that would explain failure to prune the stats collector's file
> too.
Hrm, well autovacuum is at least trying to do work: it's currently
stuck on those bloated pg_catalog tables, of course. Another developer
killed an autovacuum of pg_attribute (or maybe it was pg_attrdef)
after it had been running for two weeks. See current pg_stat_activity
output attached, which shows the three autovacuum workers running plus
two manual VACUUM ANALYZEs I started yesterday.
> Is there anything in the postmaster log that would suggest autovac
> difficulties?
Yup, there are logs from April 1st which I just grepped through. I
attached the redacted output, and I see a few warnings about "[table]
contains more than "max_fsm_pages" pages with useful free space", as
well as "ERROR: canceling autovacuum task".
Perhaps bumping up max_fsm_pages and making autovacuum settings more
aggressive will help me? I was also planning to run a CLUSTER of those
four bloated pg_catalog tables -- is this safe, particularly for
tables like pg_attrdef which rely on OIDs?
Josh
# SELECT * FROM pg_stat_activity WHERE usename = 'postgres' AND current_query
ILIKE '%vacuum%';
datid | datname | procpid | usesysid | usename |
current_query | waiting
| xact_start | query_start |
backend_start | client_addr | client_port
---------+------------+---------+----------+----------+-----------------------------------------------------------------------------------------------+---------+-------------------------------+-------------------------------+-------------------------------+---------------+-------------
7651893 | master_dev | 20288 | 10 | postgres | VACUUM ANALYZE
myschema.mytable; | f |
2010-04-14 16:24:51.421088+00 | 2010-04-14 16:24:51.421088+00 | 2010-04-14
16:24:46.875911+00 | 192.168.24.63 | 54065
[snip SELECT * FROM pg_stat_activity]
16389 | master | 9596 | 10 | postgres | autovacuum: VACUUM
ANALYZE pg_catalog.pg_attrdef | f
| 2010-04-15 21:18:41.583044+00 | 2010-04-15 21:18:41.583044+00 |
2010-04-01 11:25:53.903941+00 | |
16389 | master | 18043 | 10 | postgres | autovacuum: VACUUM
ANALYZE pg_catalog.pg_attribute | f
| 2010-04-15 17:18:36.071479+00 | 2010-04-15 17:18:36.071479+00 |
2010-04-15 16:51:50.230827+00 | |
16389 | master | 19608 | 10 | postgres | autovacuum: VACUUM
ANALYZE pg_catalog.pg_depend | f
| 2010-04-15 16:26:41.941069+00 | 2010-04-15 16:26:41.941069+00 |
2010-04-08 17:08:07.417122+00 | |
16389 | master | 20278 | 10 | postgres | VACUUM ANALYZE
myschema.mytable; | f |
2010-04-14 16:24:35.7458+00 | 2010-04-14 16:24:35.7458+00 | 2010-04-14
16:24:28.632431+00 | 192.168.24.63 | 54064
(6 rows)
# grep -A 2 -B 2 -i "vacuum" *.log
postgresql-2010-04-01_000000.log-2010-04-01 06:48:40 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 06:48:44 UTC WARNING: relation
"pg_catalog.pg_depend" contains more than "max_fsm_pages" pages with useful
free space
postgresql-2010-04-01_000000.log:2010-04-01 06:48:44 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
postgresql-2010-04-01_000000.log-2010-04-01 06:48:51 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 06:48:52 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
--
[snip connection info]
postgresql-2010-04-01_000000.log-2010-04-01 10:41:38 UTC WARNING: relation
"schema.table" contains more than "max_fsm_pages" pages with useful free space
postgresql-2010-04-01_000000.log:2010-04-01 10:41:38 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
postgresql-2010-04-01_000000.log-2010-04-01 10:41:46 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 10:41:47 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
--
postgresql-2010-04-01_000000.log-2010-04-01 10:49:33 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 10:49:33 UTC WARNING: relation
"pg_catalog.pg_depend" contains more than "max_fsm_pages" pages with useful
free space
postgresql-2010-04-01_000000.log:2010-04-01 10:49:33 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
postgresql-2010-04-01_000000.log-2010-04-01 10:49:35 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 10:49:35 UTC LOG: checkpoint
complete: wrote 73013 buffers (7.0%); 0 transaction log file(s) added, 0
removed, 57 recycled; write=179.914 s, sync=20.100 s, total=200.677 s
--
[snip connection info]
postgresql-2010-04-01_000000.log-2010-04-01 10:57:54 UTC LOG: process 9176
still waiting for ShareUpdateExclusiveLock on relation 1214 of database 0 after
1000.681 ms
postgresql-2010-04-01_000000.log:2010-04-01 10:57:54 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-01_000000.log:2010-04-01 10:57:54 UTC CONTEXT: automatic
vacuum of table "confluence.pg_catalog.pg_shdepend"
postgresql-2010-04-01_000000.log-2010-04-01 10:57:54 UTC LOG: process 9176
acquired ShareUpdateExclusiveLock on relation 1214 of database 0 after 1000.792
ms
[snip connection info]
--
postgresql-2010-04-01_000000.log-2010-04-01 10:58:52 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 10:58:54 UTC LOG: process 9180
still waiting for ShareUpdateExclusiveLock on relation 1214 of database 0 after
1000.966 ms
postgresql-2010-04-01_000000.log:2010-04-01 10:58:54 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-01_000000.log:2010-04-01 10:58:54 UTC CONTEXT: automatic
vacuum of table "postgres.pg_catalog.pg_shdepend"
postgresql-2010-04-01_000000.log-2010-04-01 10:58:54 UTC LOG: process 9180
acquired ShareUpdateExclusiveLock on relation 1214 of database 0 after 1001.930
ms
[snip connection info]
--
postgresql-2010-04-01_000000.log-2010-04-01 10:59:42 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 10:59:54 UTC LOG: process 9185
still waiting for ShareUpdateExclusiveLock on relation 1214 of database 0 after
1001.636 ms
postgresql-2010-04-01_000000.log:2010-04-01 10:59:54 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-01_000000.log:2010-04-01 10:59:54 UTC CONTEXT: automatic
vacuum of table "jira.pg_catalog.pg_shdepend"
postgresql-2010-04-01_000000.log-2010-04-01 10:59:54 UTC LOG: process 9185
acquired ShareUpdateExclusiveLock on relation 1214 of database 0 after 1004.599
ms
[snip connection info]
--
postgresql-2010-04-01_000000.log-2010-04-01 11:00:42 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-01_000000.log-2010-04-01 11:00:55 UTC LOG: process 9196
still waiting for ShareUpdateExclusiveLock on relation 1214 of database 0 after
1000.494 ms
postgresql-2010-04-01_000000.log:2010-04-01 11:00:55 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-01_000000.log:2010-04-01 11:00:55 UTC CONTEXT: automatic
vacuum of table "template1.pg_catalog.pg_shdepend"
postgresql-2010-04-01_000000.log-2010-04-01 11:00:55 UTC LOG: process 9196
acquired ShareUpdateExclusiveLock on relation 1214 of database 0 after 1000.594
ms
postgresql-2010-04-01_000000.log-2010-04-01 11:00:57 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
--
[snip connection info]
postgresql-2010-04-01_000000.log-2010-04-01 11:01:55 UTC LOG: process 9247
still waiting for ShareUpdateExclusiveLock on relation 1214 of database 0 after
1000.975 ms
postgresql-2010-04-01_000000.log:2010-04-01 11:01:55 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-01_000000.log:2010-04-01 11:01:55 UTC CONTEXT: automatic
vacuum of table "master_dev.pg_catalog.pg_shdepend"
postgresql-2010-04-01_000000.log-2010-04-01 11:01:55 UTC LOG: process 9247
acquired ShareUpdateExclusiveLock on relation 1214 of database 0 after 1002.192
ms
[snip connection info]
--
[snip connection info]
postgresql-2010-04-01_000000.log-2010-04-01 11:08:54 UTC LOG: process 9333
still waiting for ShareUpdateExclusiveLock on relation 1214 of database 0 after
1001.076 ms
postgresql-2010-04-01_000000.log:2010-04-01 11:08:54 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-01_000000.log:2010-04-01 11:08:54 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_shdepend"
postgresql-2010-04-01_000000.log-2010-04-01 11:08:54 UTC LOG: process 9333
acquired ShareUpdateExclusiveLock on relation 1214 of database 0 after 1001.170
ms
[snip connection info]
--
[snip connection info]
postgresql-2010-04-05_000000.log-2010-04-05 22:31:34 UTC WARNING: relation
"pg_catalog.pg_depend" contains more than "max_fsm_pages" pages with useful
free space
postgresql-2010-04-05_000000.log:2010-04-05 22:31:34 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
[snip connection info]
--
postgresql-2010-04-06_000000.log-2010-04-06 23:26:14 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-06_000000.log-2010-04-06 23:26:14 UTC WARNING: relation
"pg_catalog.pg_attrdef" contains more than "max_fsm_pages" pages with useful
free space
postgresql-2010-04-06_000000.log:2010-04-06 23:26:14 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
postgresql-2010-04-06_000000.log-2010-04-06 23:26:14 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-06_000000.log-2010-04-06 23:26:14 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
--
postgresql-2010-04-06_000000.log-2010-04-06 23:38:13 UTC username1 1.2.3.4
master LOG: process 18579 still waiting for ExclusiveLock on relation 2614 of
database 16389 after 1000.505 ms
postgresql-2010-04-06_000000.log-2010-04-06 23:38:13 UTC username1 1.2.3.4
master STATEMENT: COMMIT
postgresql-2010-04-06_000000.log:2010-04-06 23:38:13 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-06_000000.log:2010-04-06 23:38:13 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_listener"
postgresql-2010-04-06_000000.log-2010-04-06 23:38:13 UTC username1 1.2.3.4
master LOG: process 18579 acquired ExclusiveLock on relation 2614 of database
16389 after 1000.594 ms
postgresql-2010-04-06_000000.log-2010-04-06 23:38:13 UTC username1 1.2.3.4
master STATEMENT: COMMIT
--
[snip connection info]
postgresql-2010-04-08_000000.log-2010-04-08 16:59:05 UTC WARNING: relation
"schema.bigtable" contains more than "max_fsm_pages" pages with useful free
space
postgresql-2010-04-08_000000.log:2010-04-08 16:59:05 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
[snip connection info]
postgresql-2010-04-08_000000.log-2010-04-08 16:59:05 UTC username1 1.2.3.4
master NOTICE: there is no transaction in progress
--
postgresql-2010-04-08_000000.log-2010-04-08 19:40:14 UTC username1 1.2.3.4
master STATEMENT: CREATE TEMPORARY TABLE [snip]
postgresql-2010-04-08_000000.log-2010-04-08 19:40:14 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-08_000000.log:2010-04-08 19:40:14 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-08_000000.log:2010-04-08 19:40:14 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_type"
postgresql-2010-04-08_000000.log-2010-04-08 19:40:14 UTC username1 1.2.3.4
master LOG: process 15976 acquired AccessShareLock on relation 1247 of
database 16389 after 1023.774 ms
postgresql-2010-04-08_000000.log-2010-04-08 19:40:14 UTC username1 1.2.3.4
master STATEMENT: CREATE TEMPORARY TABLE [snip]
--
postgresql-2010-04-11_000000.log-2010-04-11 11:50:44 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-11_000000.log-2010-04-11 11:50:44 UTC WARNING: relation
"pg_catalog.pg_depend" contains more than "max_fsm_pages" pages with useful
free space
postgresql-2010-04-11_000000.log:2010-04-11 11:50:44 UTC HINT: Consider
using VACUUM FULL on this relation or increasing the configuration parameter
"max_fsm_pages".
postgresql-2010-04-11_000000.log-2010-04-11 11:50:44 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-11_000000.log-2010-04-11 11:50:44 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
--
postgresql-2010-04-12_000000.log-2010-04-12 13:02:32 UTC postgres 1.2.3.5
master LOG: process 13047 still waiting for AccessExclusiveLock on relation
25340122 of database 16389 after 1000.559 ms
postgresql-2010-04-12_000000.log-2010-04-12 13:02:32 UTC postgres 1.2.3.5
master STATEMENT: DROP TRIGGER IF EXISTS [snip]
postgresql-2010-04-12_000000.log:2010-04-12 13:02:32 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-12_000000.log:2010-04-12 13:02:32 UTC CONTEXT: automatic
vacuum of table "master.schema.table"
postgresql-2010-04-12_000000.log-2010-04-12 13:02:32 UTC postgres 1.2.3.5
master LOG: process 13047 acquired AccessExclusiveLock on relation 25340122 of
database 16389 after 1002.661 ms
postgresql-2010-04-12_000000.log-2010-04-12 13:02:32 UTC postgres 1.2.3.5
master STATEMENT: DROP TRIGGER IF EXISTS [snip]
--
postgresql-2010-04-13_000000.log-2010-04-13 17:41:46 UTC username1 1.2.3.4
master LOG: process 2725 still waiting for ExclusiveLock on relation 2614 of
database 16389 after 1001.765 ms
postgresql-2010-04-13_000000.log-2010-04-13 17:41:46 UTC username1 1.2.3.4
master STATEMENT: COMMIT
postgresql-2010-04-13_000000.log:2010-04-13 17:41:46 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-13_000000.log:2010-04-13 17:41:46 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_listener"
postgresql-2010-04-13_000000.log-2010-04-13 17:41:46 UTC username1 1.2.3.4
master LOG: process 2725 acquired ExclusiveLock on relation 2614 of database
16389 after 1001.886 ms
postgresql-2010-04-13_000000.log-2010-04-13 17:41:46 UTC username1 1.2.3.4
master STATEMENT: COMMIT
--
postgresql-2010-04-15_000000.log-2010-04-15 16:12:37 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-15_000000.log-2010-04-15 16:12:38 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-15_000000.log:2010-04-15 16:12:38 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-15_000000.log:2010-04-15 16:12:38 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_attrdef"
postgresql-2010-04-15_000000.log-2010-04-15 16:12:39 UTC username1 1.2.3.4
master LOG: process 9599 still waiting for AccessShareLock on relation
11969189 of database 16389 after 1001.789 ms
postgresql-2010-04-15_000000.log-2010-04-15 16:12:39 UTC username1 1.2.3.4
master STATEMENT: CREATE TEMPORARY TABLE [snip]
--
postgresql-2010-04-15_000000.log-2010-04-15 16:12:44 UTC username1 1.2.3.4
master LOG: process 27873 still waiting for AccessShareLock on relation
11969189 of database 16389 after 1000.468 ms
postgresql-2010-04-15_000000.log-2010-04-15 16:12:44 UTC username1 1.2.3.4
master STATEMENT: CREATE TEMPORARY TABLE [snip]
postgresql-2010-04-15_000000.log:2010-04-15 16:12:45 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-15_000000.log:2010-04-15 16:12:45 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_depend"
postgresql-2010-04-15_000000.log:2010-04-15 16:12:51 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-15_000000.log:2010-04-15 16:12:51 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_attribute"
[snip connection info]
--
postgresql-2010-04-15_000000.log-2010-04-15 16:26:41 UTC username1 1.2.3.4
master LOG: process 16378 still waiting for ExclusiveLock on relation 2614 of
database 16389 after 1001.038 ms
postgresql-2010-04-15_000000.log-2010-04-15 16:26:41 UTC username1 1.2.3.4
master STATEMENT: COMMIT
postgresql-2010-04-15_000000.log:2010-04-15 16:26:41 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-15_000000.log:2010-04-15 16:26:41 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_listener"
postgresql-2010-04-15_000000.log-2010-04-15 16:26:41 UTC username1 1.2.3.4
master LOG: process 16378 acquired ExclusiveLock on relation 2614 of database
16389 after 1001.166 ms
postgresql-2010-04-15_000000.log-2010-04-15 16:26:41 UTC username1 1.2.3.4
master STATEMENT: COMMIT
--
postgresql-2010-04-15_000000.log-2010-04-15 16:32:37 UTC username1 1.2.3.4
master LOG: process 16702 still waiting for AccessExclusiveLock on relation
11969302 of database 16389 after 1000.550 ms
postgresql-2010-04-15_000000.log-2010-04-15 16:32:37 UTC username1 1.2.3.4
master STATEMENT: DROP INDEX IF EXISTS [snip]
postgresql-2010-04-15_000000.log:2010-04-15 16:32:37 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-15_000000.log-2010-04-15 16:32:37 UTC CONTEXT: automatic
analyze of table "master.schema.another_big_table"
postgresql-2010-04-15_000000.log-2010-04-15 16:32:37 UTC username1 1.2.3.4
master LOG: process 16702 acquired AccessExclusiveLock on relation 11969302 of
database 16389 after 1000.621 ms
--
postgresql-2010-04-15_000000.log-2010-04-15 17:18:36 UTC username1 1.2.3.4
master LOG: process 9599 acquired AccessShareLock on relation 1247 of database
16389 after 1644.619 ms
postgresql-2010-04-15_000000.log-2010-04-15 17:18:36 UTC username1 1.2.3.4
master STATEMENT: CREATE TEMPORARY TABLE [snip]
postgresql-2010-04-15_000000.log:2010-04-15 17:18:36 UTC ERROR: canceling
autovacuum task
postgresql-2010-04-15_000000.log:2010-04-15 17:18:36 UTC CONTEXT: automatic
vacuum of table "master.pg_catalog.pg_type"
postgresql-2010-04-15_000000.log-2010-04-15 17:18:36 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
postgresql-2010-04-15_000000.log-2010-04-15 17:18:36 UTC username1 1.2.3.4
master WARNING: there is already a transaction in progress
--
--
Sent via pgsql-performance mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
