On Fri, Apr 16, 2010 at 11:41 AM, Tom Lane <tgl@xxxxxxxxxxxxx> 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 (pgsql-performance@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
