Skip site navigation (1) Skip section navigation (2)

Re: Vacuum Full Analyze Stalled

From: "Kevin Grittner" <Kevin(dot)Grittner(at)wicourts(dot)gov>
To: <tgl(at)sss(dot)pgh(dot)pa(dot)us>, "Jeff Kirby" <Jeff(dot)Kirby(at)wicourts(dot)gov>
Cc: <pgsql-admin(at)postgresql(dot)org>
Subject: Re: Vacuum Full Analyze Stalled
Date: 2005-10-03 19:09:37
Message-ID: s3413ba7.062@gwmta.wicourts.gov (view raw or flat)
Thread:
Lists: pgsql-adminpgsql-hackers
The previous report was from the same databases -- I'm a consultant
tasked with evaluating the various open source options and making
one of them work with our existing framework.  Jeff developed a new
app (which is in beta testing) which is our first use of PostgreSQL
with real production load for prolonged periods of time.
 
Jeff was monitoring the app over the weekend, and posted here when
he had problems.  Unfortunately, he didn't capture enough information
to diagnose much, but I'm passing along the sequence of events
since they lead up to a failure this morning for which we have more
detail.
 
Saturday, 9:00 a.m. -- Noticed performace beginning to degrade.
Saturday, 1:00 p.m. -- After continued degradation, stops client app,
   and runs vacuum full analyze on both Windows and Linux boxes.
Saturday, 3:00 p.m. -- Windows box completes the vacuum.
Sunday, 1:00 p.m. -- Vacuum on Linux still not done.  CPU on Linux
   box is completely idle.  Killed the vacuum process.  Ran vacuum
   full analyze on each table individually.  All fine except for the 72 row
   table with very frequent updates.  Left this one running.
Sunday, 9:00 p.m. -- Vacuum of 72 row table still running.  Killed all
   processes and restarted postgres.  Started a vacuum full analyze
   of the 72 row table again.
Sunday, 11:00 p.m. -- Vacuum of 72 row table finishes.  Started
   applications, which had been stopped since Saturday, 1:00 p.m.
Monday, 9:20 a.m. -- Performance is beginning to degrade again.
   Detailed information from this point below.
 
dtr=# select * from pg_locks order by pid;
   locktype    | database | relation | page | tuple | transactionid | classid | objid | objsubid | transaction | pid  |           mode           | granted
---------------+----------+----------+------+-------+---------------+---------+-------+----------+-------------+------+--------------------------+---------
 transactionid |          |          |      |       |      36430565 |         |       |          |    36430565 | 2771 | ExclusiveLock            | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430565 | 2771 | AccessShareLock          | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430565 | 2771 | RowExclusiveLock         | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430565 | 2771 | AccessShareLock          | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430565 | 2771 | RowExclusiveLock         | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430561 | 2777 | AccessShareLock          | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430561 | 2777 | RowExclusiveLock         | t
 transactionid |          |          |      |       |      36430561 |         |       |          |    36430561 | 2777 | ExclusiveLock            | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430561 | 2777 | AccessShareLock          | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430561 | 2777 | RowExclusiveLock         | t
 transactionid |          |          |      |       |      36430563 |         |       |          |    36430563 | 2783 | ExclusiveLock            | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430563 | 2783 | AccessShareLock          | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430563 | 2783 | RowExclusiveLock         | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430563 | 2783 | AccessShareLock          | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430563 | 2783 | RowExclusiveLock         | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430559 | 2790 | AccessShareLock          | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    36430559 | 2790 | RowExclusiveLock         | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430559 | 2790 | AccessShareLock          | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    36430559 | 2790 | RowExclusiveLock         | t
 transactionid |          |          |      |       |      36430559 |         |       |          |    36430559 | 2790 | ExclusiveLock            | t
 relation      |    30793 |    30976 |      |       |               |         |       |          |    35633343 | 3158 | ShareUpdateExclusiveLock | t
 transactionid |          |          |      |       |      35633343 |         |       |          |    35633343 | 3158 | ExclusiveLock            | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    35633343 | 3158 | ShareUpdateExclusiveLock | t
 relation      |    30793 |    10340 |      |       |               |         |       |          |    36430567 | 4238 | AccessShareLock          | t
 transactionid |          |          |      |       |      36430567 |         |       |          |    36430567 | 4238 | ExclusiveLock            | t
(25 rows)

dtr=# \q
postgres(at)linpost:/var/pgsql/data> ps aux|grep ^postgres
postgres 28937  0.0  0.0  2436  992 pts/1    S    Sep30   0:00 su postgres
postgres 28938  0.0  0.0  2944 1620 pts/1    S    Sep30   0:00 bash
postgres  2612  0.0  0.0 170968 4952 ?       S    Oct02   0:00 /usr/local/pgsql/bin/postmaster
postgres  2614  0.0  1.9 171200 165528 ?     S    Oct02   0:08 postgres: writer process
postgres  2615  0.0  0.0  7240 2788 ?        S    Oct02   0:27 postgres: stats buffer process
postgres  2617  0.0  0.0  6556 1988 ?        S    Oct02   0:22 postgres: stats collector process
postgres  2724  0.0  0.0 171828 7156 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32986) idle
postgres  2771  6.4  2.0 171996 167176 ?     S    Oct02  44:33 postgres: dtr dtr 127.0.0.1(32990) idle
postgres  2773  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32991) idle
postgres  2774  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32992) idle
postgres  2775  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32993) idle
postgres  2776  0.0  0.0 171720 6848 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32994) idle
postgres  2777  6.4  2.0 171996 167228 ?     R    Oct02  44:29 postgres: dtr dtr 127.0.0.1(32995) UPDATE
postgres  2778  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32996) idle
postgres  2779  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32997) idle
postgres  2780  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32998) idle
postgres  2781  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(32999) idle
postgres  2782  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(33000) idle
postgres  2783  6.4  2.0 172016 167292 ?     S    Oct02  44:38 postgres: dtr dtr 127.0.0.1(33001) idle
postgres  2784  0.0  0.0 171460 5824 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(33002) idle
postgres  2785  0.0  0.0 171460 5828 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(33003) idle
postgres  2786  6.4  2.0 172000 167216 ?     S    Oct02  44:38 postgres: dtr dtr 127.0.0.1(33004) idle
postgres  2787  6.4  2.0 172000 167236 ?     R    Oct02  44:33 postgres: dtr dtr 127.0.0.1(33005) UPDATE
postgres  2788  0.0  0.0 171460 5828 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(33006) idle
postgres  2789  0.0  0.0 171460 5828 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(33007) idle
postgres  2790  6.4  2.0 171992 167280 ?     R    Oct02  44:27 postgres: dtr dtr 127.0.0.1(33008) UPDATE
postgres  2791  0.0  0.0 171460 5828 ?       S    Oct02   0:00 postgres: dtr dtr 127.0.0.1(33009) idle
postgres  3158  0.0  0.0 188324 8044 ?       S    Oct02   0:00 postgres: autovacuum process   dtr
postgres  4289  0.0  0.0  2148  672 pts/1    R+   09:21   0:00 ps aux
postgres  4290  0.0  0.0  1688  688 pts/1    R+   09:21   0:00 grep ^postgres
 
oid 30871 is the 72 row table.
oid 30976 is the index for its primary key.
 
We stopped the applications, and the autovacuum process didn't
wake up.
 
dtr=# select * from pg_locks order by pid;
   locktype    | database | relation | page | tuple | transactionid | classid | objid | objsubid | transaction | pid  |           mode           | granted
---------------+----------+----------+------+-------+---------------+---------+-------+----------+-------------+------+--------------------------+---------
 relation      |    30793 |    30976 |      |       |               |         |       |          |    35633343 | 3158 | ShareUpdateExclusiveLock | t
 transactionid |          |          |      |       |      35633343 |         |       |          |    35633343 | 3158 | ExclusiveLock            | t
 relation      |    30793 |    30871 |      |       |               |         |       |          |    35633343 | 3158 | ShareUpdateExclusiveLock | t
 relation      |    30793 |    10340 |      |       |               |         |       |          |    36600517 | 4498 | AccessShareLock          | t
 transactionid |          |          |      |       |      36600517 |         |       |          |    36600517 | 4498 | ExclusiveLock            | t
(5 rows)

dtr=# \q
postgres(at)linpost:/var/pgsql/data> ps aux|grep ^postgres
postgres  2612  0.0  0.0 170968 4952 ?       S    Oct02   0:00 /usr/local/pgsql/bin/postmaster
postgres  2614  0.0  1.9 171200 165528 ?     S    Oct02   0:10 postgres: writer process
postgres  2615  0.0  0.0  7240 2788 ?        S    Oct02   0:32 postgres: stats buffer process
postgres  2617  0.0  0.0  6556 1988 ?        S    Oct02   0:26 postgres: stats collector process
postgres  3158  0.0  0.0 188324 8044 ?       S    Oct02   0:00 postgres: autovacuum process   dtr
postgres  4481  0.0  0.0  2432  988 pts/1    S    10:48   0:00 su postgres
postgres  4482  0.0  0.0  2944 1604 pts/1    S    10:48   0:00 bash
postgres  4499  0.0  0.0  2148  672 pts/1    R+   10:49   0:00 ps aux
postgres  4500  0.0  0.0  1680  636 pts/1    S+   10:49   0:00 grep ^postgres
postgres(at)linpost:/var/pgsql/data> uptime
 10:48am  up 6 days 19:20,  2 users,  load average: 0.00, 0.28, 0.73
postgres(at)linpost:/var/pgsql/data> vmstat 10
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
 0  0      8 278376  62676 7770684    0    0    15     7   17    18 11  1 87  1
 0  0      8 278376  62700 7770660    0    0     0    11 1035     0  1  0 99  0
 0  0      8 278440  62700 7770660    0    0     0     0 1013     0  0  0 100  0
 0  0      8 278440  62700 7770660    0    0     0     0 1016     0  1  0 99  0
 0  0      8 278440  62700 7770660    0    0     0     4 1018     0  1  0 99  0
 
We found the 72 row table somewhat bloated, so we cleaned it up.
 
dtr=# vacuum analyze verbose "DbTranImageStatus";
INFO:  vacuuming "public.DbTranImageStatus"
INFO:  index "DbTranImageStatusPK" now contains 72 row versions in 6665 pages
DETAIL:  6555 index pages have been deleted, 6555 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.01 sec.
INFO:  "DbTranImageStatus": found 0 removable, 72 nonremovable row versions in 4244 pages
DETAIL:  0 dead row versions cannot be removed yet.
There were 479137 unused item pointers.
0 pages are entirely empty.
CPU 0.01s/0.01u sec elapsed 0.02 sec.
INFO:  vacuuming "pg_toast.pg_toast_272793"
INFO:  index "pg_toast_272793_index" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  "pg_toast_272793": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL:  0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  analyzing "public.DbTranImageStatus"
INFO:  "DbTranImageStatus": scanned 3000 of 4244 pages, containing 68 live rows and 0 dead rows; 68 rows in sample, 96 estimated total rows
VACUUM
dtr=# vacuum full analyze verbose "DbTranImageStatus";
INFO:  vacuuming "public.DbTranImageStatus"
INFO:  "DbTranImageStatus": found 0 removable, 72 nonremovable row versions in 4244 pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 68 to 68 bytes long.
There were 479137 unused item pointers.
Total free space (including removable row versions) is 32760236 bytes.
4227 pages are or will become empty, including 0 at the end of the table.
4244 pages containing 32760236 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  index "DbTranImageStatusPK" now contains 72 row versions in 6654 pages
DETAIL:  0 index row versions were removed.
6544 index pages have been deleted, 6544 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  "DbTranImageStatus": moved 22 row versions, truncated 4244 to 1 pages
DETAIL:  CPU 0.00s/0.02u sec elapsed 0.03 sec.
INFO:  index "DbTranImageStatusPK" now contains 72 row versions in 6654 pages
DETAIL:  22 index row versions were removed.
6544 index pages have been deleted, 6544 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  vacuuming "pg_toast.pg_toast_272793"
INFO:  "pg_toast_272793": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 0 to 0 bytes long.
There were 0 unused item pointers.
Total free space (including removable row versions) is 0 bytes.
0 pages are or will become empty, including 0 at the end of the table.
0 pages containing 0 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  index "pg_toast_272793_index" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  analyzing "public.DbTranImageStatus"
INFO:  "DbTranImageStatus": scanned 1 of 1 pages, containing 72 live rows and 0 dead rows; 72 rows in sample, 72 estimated total rows
VACUUM
dtr=# reindex table "DbTranImageStatus";
REINDEX
dtr=# vacuum analyze verbose "DbTranImageStatus";
INFO:  vacuuming "public.DbTranImageStatus"
INFO:  index "DbTranImageStatusPK" now contains 72 row versions in 2 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  "DbTranImageStatus": found 0 removable, 72 nonremovable row versions in 1 pages
DETAIL:  0 dead row versions cannot be removed yet.
There were 48 unused item pointers.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  vacuuming "pg_toast.pg_toast_272793"
INFO:  index "pg_toast_272793_index" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  "pg_toast_272793": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL:  0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  analyzing "public.DbTranImageStatus"
INFO:  "DbTranImageStatus": scanned 1 of 1 pages, containing 72 live rows and 0 dead rows; 72 rows in sample, 72 estimated total rows
VACUUM
 
These all ran sub-second.  We updated postgresql.conf for more
aggressive autovacuum, and restarted postgres, then restarted the
application.
 
This failure seems rather different from the one I previously posted,
since it was blocking on the application table, rather than
pg_constraint_contypid_index, and it did not wake up when all
other processes where stopped.
 
As before, both boxes are running 8.1beta2.  Windows is not showing
these problems with the autovacuum blocking; just Linux.
 
-Kevin
 
 
>>> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> 10/02/05 8:53 PM >>>
"Jeff Kirby" <Jeff(dot)Kirby(at)wicourts(dot)gov> writes:
> the Linux box however is still chugging away this morning... and
> appears to be stuck on vacuuming "pg_constraint_contypid_index".  How
> do I know... well I don't really... I'm inferring based on the order
> of the log output on the Windows box.

Looking in pg_locks would give you a more reliable indicator of what the
VACUUM is currently working on.

Is the Linux box otherwise idle?  There was another report recently of a
vacuum hung up for a long time on pg_constraint_contypid_index, but it
seemed to be due to extremely heavy usage of domain types ...

			regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

               http://archives.postgresql.org


Responses

pgsql-hackers by date

Next:From: David FetterDate: 2005-10-03 19:21:21
Subject: Re: [HACKERS] External Sort timing debug statements
Previous:From: Jeff FrostDate: 2005-10-03 18:25:25
Subject: Replaying archived wal files after a dump restore?

pgsql-admin by date

Next:From: Kevin GrittnerDate: 2005-10-03 19:38:56
Subject: Re: Vacuum Full Analyze Stalled
Previous:From: Joshua OrtDate: 2005-10-03 18:59:22
Subject: PostgreSQL error (new user)

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group