Re: Vacuum Full Analyze Stalled

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