Thread: database vacuum from cron hanging

database vacuum from cron hanging

From
"Kevin Grittner"
Date:
This may or may not be related to previous threads regarding vacuum problems.
Following the last thread, we built the development snapshot of Oct 6 with
--enable-integer-datetimes and --enable-debug.  We have had the autovacuum
running every ten seconds.  The only table which will meet the autovacuum
criteria is a table with 72 rows which is frequently updated.  This part was doing
fine -- keeping the pages to about 20 without any noticable performance hit.
We also set up nightly crontab jobs:
# Do a vacuum of the dtr database every evening starting at 6:00 p.m.
0 18 * * * /usr/local/pgsql/bin/psql -c "vacuum analyze verbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1
# Do a dump of the dtr database every evening starting at 8:00 p.m.
0 20 * * * /usr/local/pgsql/bin/pg_dump -f /var/pgsql/data/dumps/dtr.dump -Fc dtr
I checked the output files from these after the first night, and all seemed well.
There were messages at the end regarding the fsm settings, but after close
review and checking the archives, decided it was OK.  I guess I failed to run a ps
on the postgres user, or failed to notice the process that was left hanging.
Anyway, after complaints that the server was getting slow today, I took another
look.  Below is a cut and paste from my ssh session.
dtr2:/var/pgsql/data # ps aux|grep ^postgres
postgres 29479  0.0  0.0 172112  4984 ?        S    Oct07   0:03 /usr/local/pgsql/bin/postmaster -D /var/pgsql/data
postgres 29481  0.0  1.9 172296 165296 ?       S    Oct07   0:12 postgres: writer process
postgres 29482  0.0  0.0   7908  2816 ?        S    Oct07   0:43 postgres: stats buffer process
postgres 29483  0.0  0.0   7228  2028 ?        S    Oct07   0:43 postgres: stats collector process
postgres 30948  0.0  0.0 172968  8124 ?        S    Oct07   0:00 postgres: dtr dtr 127.0.0.1(32794) idle
postgres   744  0.0  0.0   2440  1056 ?        Ss   Oct07   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres   746  0.0  0.0   3200  1004 ?        S    Oct07   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres   748  0.0  0.0 190008  7544 ?        S    Oct07   0:00 postgres: postgres dtr [local] VACUUM
postgres 12664  0.0  0.0   2440  1052 ?        Ss   Oct08   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres 12666  0.0  0.0   3200  1004 ?        S    Oct08   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 12687  0.0  0.0 173636  7572 ?        S    Oct08   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres 24647  0.0  0.0   2440  1052 ?        Ss   Oct09   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres 24649  0.0  0.0   3200  1000 ?        S    Oct09   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 24670  0.0  0.0 173636  7888 ?        S    Oct09   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres  4273  0.0  0.0   2440  1056 ?        Ss   Oct10   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres  4275  0.0  0.0   3200  1004 ?        S    Oct10   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres  4281  0.0  0.0 173104  7512 ?        S    Oct10   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres 14689  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32863) idle
postgres 14690  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32864) idle
postgres 14691  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32865) idle
postgres 14692  0.0  0.0 172864  6944 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32866) idle
postgres 14693  0.0  0.1 173128  8632 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32867) idle
postgres 14694 15.9  1.4 173112 120924 ?       R    11:33  14:27 postgres: dtr dtr 127.0.0.1(32868) UPDATE
postgres 14695  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32869) idle
postgres 14696  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32870) idle
postgres 14697  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32871) idle
postgres 14698  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32872) idle
postgres 14699  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32873) idle
postgres 14700 16.0  1.4 173116 120532 ?       S    11:33  14:27 postgres: dtr dtr 127.0.0.1(32874) idle
postgres 14701  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32875) idle
postgres 14702  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32876) idle
postgres 14703 16.0  1.4 173108 121692 ?       S    11:33  14:28 postgres: dtr dtr 127.0.0.1(32877) idle
postgres 14704 15.9  1.4 173068 120704 ?       S    11:33  14:24 postgres: dtr dtr 127.0.0.1(32878) idle
postgres 14705  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32879) idle
postgres 14706  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32880) idle
postgres 14707 15.9  1.4 173112 120448 ?       S    11:33  14:23 postgres: dtr dtr 127.0.0.1(32881) idle
postgres 14708 15.8  1.4 173108 120144 ?       S    11:33  14:17 postgres: dtr dtr 127.0.0.1(32882) idle
postgres 14961  0.0  0.1 173128  9692 ?        S    12:03   0:00 postgres: dtr dtr 165.219.88.90(54422) idle
postgres 14963  0.0  0.0 172604  5880 ?        S    12:03   0:00 postgres: dtr dtr 165.219.88.90(54424) idle
postgres 14970  0.0  0.1 173080 13440 ?        S    12:04   0:00 postgres: dtr dtr 165.219.88.90(54430) idle
postgres 15021  0.0  0.0 172604  5880 ?        S    12:12   0:00 postgres: dtr dtr 165.219.88.90(54452) idle
dtr2:/var/pgsql/data # strace -tt -p 4281
Process 4281 attached - interrupt to quit
13:03:57.061515 semop(4980740, 0xbfffc430, 1 <unfinished ...>
Process 4281 detached
dtr2:/var/pgsql/data # gdb
GNU gdb 6.3
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i586-suse-linux".
(gdb) attach 4281
Attaching to process 4281
Reading symbols from /usr/local/pgsql/bin/postgres...done.
Using host libthread_db library "/lib/libthread_db.so.1".
Reading symbols from /lib/libz.so.1...done.
Loaded symbols for /lib/libz.so.1
Reading symbols from /lib/libreadline.so.5...done.
Loaded symbols for /lib/libreadline.so.5
Reading symbols from /lib/libcrypt.so.1...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /lib/libresolv.so.2...done.
Loaded symbols for /lib/libresolv.so.2
Reading symbols from /lib/libnsl.so.1...done.
Loaded symbols for /lib/libnsl.so.1
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/i686/libm.so.6...done.
Loaded symbols for /lib/i686/libm.so.6
Reading symbols from /lib/i686/libc.so.6...done.
Loaded symbols for /lib/i686/libc.so.6
Reading symbols from /lib/libncurses.so.5...done.
Loaded symbols for /lib/libncurses.so.5
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
0x401aac58 in semop () from /lib/i686/libc.so.6
(gdb) bt
#0  0x401aac58 in semop () from /lib/i686/libc.so.6
#1  0x0816a3d4 in PGSemaphoreLock (sema=0x0, interruptOK=1 '\001') at pg_sema.c:418
#2  0x0818d260 in ProcSleep (lockMethodTable=0x4a2a520c, lockmode=4, lock=0x4a31b3a0, proclock=0x4a340be8) at
proc.c:757
#3  0x0818c558 in LockAcquire (lockmethodid=1, locktag=0xbfffc540, isTempObject=0 '\0', lockmode=4, sessionLock=0 '\0',
dontWait=0'\0') at lock.c:1090 
#4  0x0818a8f9 in LockRelation (relation=0x4a585ce0, lockmode=4) at lmgr.c:144
#5  0x0808c909 in relation_open (relationId=2606, lockmode=4) at heapam.c:454
#6  0x08118d3a in vacuum_rel (relid=2606, vacstmt=0x83471c8, expected_relkind=114 'r') at vacuum.c:1005
#7  0x0811a23b in vacuum (vacstmt=0x83471c8, relids=0x0) at vacuum.c:450
#8  0x08196bf6 in PortalRunUtility (portal=0x834ef28, query=0x8347260, dest=0x8347218, completionTag=0xbfffcb00 "") at
pquery.c:991
#9  0x08198099 in PortalRun (portal=0x834ef28, count=2147483647, dest=0x8347218, altdest=0x8347218,
completionTag=0xbfffcb00"") at pquery.c:1058 
#10 0x08193b48 in exec_simple_query (query_string=0x8346f08 "vacuum analyze verbose;") at postgres.c:1017
#11 0x0819570a in PostgresMain (argc=4, argv=0x82ec108, username=0x82ec0e0 "postgres") at postgres.c:3184
#12 0x081716e5 in ServerLoop () at postmaster.c:2862
#13 0x0817235e in PostmasterMain (argc=3, argv=0x82e9d38) at postmaster.c:941
#14 0x0813aab8 in main (argc=3, argv=0x82e9d38) at main.c:268
(gdb) quit
The program is running.  Quit anyway (and detach it)? (y or n) y
Detaching from program: /usr/local/pgsql/bin/postgres, process 4281
dtr2:/var/pgsql/data # ps aux|grep ^postgres
postgres 29479  0.0  0.0 172112  4984 ?        S    Oct07   0:03 /usr/local/pgsql/bin/postmaster -D /var/pgsql/data
postgres 29481  0.0  1.9 172296 165296 ?       S    Oct07   0:12 postgres: writer process
postgres 29482  0.0  0.0   7908  2816 ?        S    Oct07   0:43 postgres: stats buffer process
postgres 29483  0.0  0.0   7228  2028 ?        S    Oct07   0:43 postgres: stats collector process
postgres 30948  0.0  0.0 172968  8124 ?        S    Oct07   0:00 postgres: dtr dtr 127.0.0.1(32794) idle
postgres   744  0.0  0.0   2440  1056 ?        Ss   Oct07   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres   746  0.0  0.0   3200  1004 ?        S    Oct07   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres   748  0.0  0.0 190008  7544 ?        S    Oct07   0:00 postgres: postgres dtr [local] VACUUM
postgres 12664  0.0  0.0   2440  1052 ?        Ss   Oct08   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres 12666  0.0  0.0   3200  1004 ?        S    Oct08   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 12687  0.0  0.0 173636  7572 ?        S    Oct08   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres 24647  0.0  0.0   2440  1052 ?        Ss   Oct09   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres 24649  0.0  0.0   3200  1000 ?        S    Oct09   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 24670  0.0  0.0 173636  7888 ?        S    Oct09   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres  4273  0.0  0.0   2440  1056 ?        Ss   Oct10   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres  4275  0.0  0.0   3200  1004 ?        S    Oct10   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 14689  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32863) idle
postgres 14690  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32864) idle
postgres 14691  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32865) idle
postgres 14692  0.0  0.0 172864  6944 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32866) idle
postgres 14693  0.0  0.1 173128  8632 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32867) idle
postgres 14694 16.0  1.4 173112 121268 ?       S    11:33  14:43 postgres: dtr dtr 127.0.0.1(32868) idle
postgres 14695  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32869) idle
postgres 14696  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32870) idle
postgres 14697  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32871) idle
postgres 14698  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32872) idle
postgres 14699  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32873) idle
postgres 14700 16.0  1.4 173116 120912 ?       S    11:33  14:43 postgres: dtr dtr 127.0.0.1(32874) idle
postgres 14701  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32875) idle
postgres 14702  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32876) idle
postgres 14703 16.0  1.4 173108 122108 ?       S    11:33  14:43 postgres: dtr dtr 127.0.0.1(32877) idle
postgres 14704 15.9  1.4 173068 121288 ?       S    11:33  14:36 postgres: dtr dtr 127.0.0.1(32878) idle
postgres 14705  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32879) idle
postgres 14706  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32880) idle
postgres 14707 15.9  1.4 173112 120864 ?       S    11:33  14:35 postgres: dtr dtr 127.0.0.1(32881) idle
postgres 14708 15.8  1.4 173108 120540 ?       R    11:33  14:30 postgres: dtr dtr 127.0.0.1(32882) UPDATE
postgres 14961  0.0  0.1 173128  9692 ?        S    12:03   0:00 postgres: dtr dtr 165.219.88.90(54422) idle
postgres 14963  0.0  0.0 172604  5880 ?        S    12:03   0:00 postgres: dtr dtr 165.219.88.90(54424) idle
postgres 14970  0.0  0.1 173080 13440 ?        S    12:04   0:00 postgres: dtr dtr 165.219.88.90(54430) idle
postgres 15021  0.0  0.0 172604  5880 ?        S    12:12   0:00 postgres: dtr dtr 165.219.88.90(54452) idle
postgres  4281  0.0  0.0 173104  7512 ?        S    Oct10   0:00 postgres: postgres dtr [local] VACUUM waiting
dtr2:/var/pgsql/data # gdb
GNU gdb 6.3
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i586-suse-linux".
(gdb) attach 748
Attaching to process 748
Reading symbols from /usr/local/pgsql/bin/postgres...done.
Using host libthread_db library "/lib/libthread_db.so.1".
[snip]
0x401aac58 in semop () from /lib/i686/libc.so.6
(gdb) bt
#0  0x401aac58 in semop () from /lib/i686/libc.so.6
#1  0x0816a3d4 in PGSemaphoreLock (sema=0x0, interruptOK=1 '\001') at pg_sema.c:418
#2  0x0818cf96 in ProcWaitForSignal () at proc.c:985
#3  0x0818171e in LockBufferForCleanup (buffer=782) at bufmgr.c:1859
#4  0x08093c9a in btbulkdelete (fcinfo=0xfffffffc) at nbtree.c:639
#5  0x082031d7 in FunctionCall3 (flinfo=0x1, arg1=4294967292, arg2=4294967292, arg3=4294967292) at fmgr.c:1182
#6  0x0808f054 in index_bulk_delete (indexRelation=0x4a59d960, callback=0x811aa20 <dummy_tid_reaped>,
callback_state=0x0)at indexam.c:687 
#7  0x0811ba85 in lazy_vacuum_rel (onerel=0x4a572ea0, vacstmt=0x8347088) at vacuumlazy.c:625
#8  0x081193c2 in vacuum_rel (relid=<value optimized out>, vacstmt=0x8347088, expected_relkind=114 'r') at
vacuum.c:1074
#9  0x0811a23b in vacuum (vacstmt=0x8347088, relids=0x0) at vacuum.c:450
#10 0x08196bf6 in PortalRunUtility (portal=0x834ede8, query=0x8347120, dest=0x83470d8, completionTag=0xbfffcb00 "") at
pquery.c:991
#11 0x08198099 in PortalRun (portal=0x834ede8, count=2147483647, dest=0x83470d8, altdest=0x83470d8,
completionTag=0xbfffcb00"") at pquery.c:1058 
#12 0x08193b48 in exec_simple_query (query_string=0x8346dc8 "vacuum analyze verbose;") at postgres.c:1017
#13 0x0819570a in PostgresMain (argc=4, argv=0x82ec108, username=0x82ec0e0 "postgres") at postgres.c:3184
#14 0x081716e5 in ServerLoop () at postmaster.c:2862
#15 0x0817235e in PostmasterMain (argc=3, argv=0x82e9d38) at postmaster.c:941
#16 0x0813aab8 in main (argc=3, argv=0x82e9d38) at main.c:268
(gdb) detach
Detaching from program: /usr/local/pgsql/bin/postgres, process 748
(gdb) attach 12687
Attaching to program: /usr/local/pgsql/bin/postgres, process 12687
Symbols already loaded for /lib/libz.so.1
[snip]
0x401aac58 in semop () from /lib/i686/libc.so.6
(gdb) bt
#0  0x401aac58 in semop () from /lib/i686/libc.so.6
#1  0x0816a3d4 in PGSemaphoreLock (sema=0x0, interruptOK=1 '\001') at pg_sema.c:418
#2  0x0818d260 in ProcSleep (lockMethodTable=0x4a2a520c, lockmode=4, lock=0x4a31b3a0, proclock=0x4a340b70) at
proc.c:757
#3  0x0818c558 in LockAcquire (lockmethodid=1, locktag=0xbfffc540, isTempObject=0 '\0', lockmode=4, sessionLock=0 '\0',
dontWait=0'\0') at lock.c:1090 
#4  0x0818a8f9 in LockRelation (relation=0x4a572ea0, lockmode=4) at lmgr.c:144
#5  0x0808c909 in relation_open (relationId=2606, lockmode=4) at heapam.c:454
#6  0x08118d3a in vacuum_rel (relid=2606, vacstmt=0x83470b0, expected_relkind=114 'r') at vacuum.c:1005
#7  0x0811a23b in vacuum (vacstmt=0x83470b0, relids=0x0) at vacuum.c:450
#8  0x08196bf6 in PortalRunUtility (portal=0x83512a0, query=0x8347148, dest=0x8347100, completionTag=0xbfffcb00 "") at
pquery.c:991
#9  0x08198099 in PortalRun (portal=0x83512a0, count=2147483647, dest=0x8347100, altdest=0x8347100,
completionTag=0xbfffcb00"") at pquery.c:1058 
#10 0x08193b48 in exec_simple_query (query_string=0x8346df0 "vacuum analyze verbose;") at postgres.c:1017
#11 0x0819570a in PostgresMain (argc=4, argv=0x82ec108, username=0x82ec0e0 "postgres") at postgres.c:3184
#12 0x081716e5 in ServerLoop () at postmaster.c:2862
#13 0x0817235e in PostmasterMain (argc=3, argv=0x82e9d38) at postmaster.c:941
#14 0x0813aab8 in main (argc=3, argv=0x82e9d38) at main.c:268
(gdb) detach 12687
Detaching from program: /usr/local/pgsql/bin/postgres, process 12687
ptrace: Input/output error.
(gdb) detach
Detaching from program: /usr/local/pgsql/bin/postgres, process 12687
(gdb) attach 24670
Attaching to program: /usr/local/pgsql/bin/postgres, process 24670
Symbols already loaded for /lib/libz.so.1
[snip]
0x401aac58 in semop () from /lib/i686/libc.so.6
(gdb) bt
#0  0x401aac58 in semop () from /lib/i686/libc.so.6
#1  0x0816a3d4 in PGSemaphoreLock (sema=0x0, interruptOK=1 '\001') at pg_sema.c:418
#2  0x0818d260 in ProcSleep (lockMethodTable=0x4a2a520c, lockmode=4, lock=0x4a31b3a0, proclock=0x4a3409e0) at
proc.c:757
#3  0x0818c558 in LockAcquire (lockmethodid=1, locktag=0xbfffc540, isTempObject=0 '\0', lockmode=4, sessionLock=0 '\0',
dontWait=0'\0') at lock.c:1090 
#4  0x0818a8f9 in LockRelation (relation=0x4a572ea0, lockmode=4) at lmgr.c:144
#5  0x0808c909 in relation_open (relationId=2606, lockmode=4) at heapam.c:454
#6  0x08118d3a in vacuum_rel (relid=2606, vacstmt=0x83470d8, expected_relkind=114 'r') at vacuum.c:1005
#7  0x0811a23b in vacuum (vacstmt=0x83470d8, relids=0x0) at vacuum.c:450
#8  0x08196bf6 in PortalRunUtility (portal=0x83512c8, query=0x8347170, dest=0x8347128, completionTag=0xbfffcb00 "") at
pquery.c:991
#9  0x08198099 in PortalRun (portal=0x83512c8, count=2147483647, dest=0x8347128, altdest=0x8347128,
completionTag=0xbfffcb00"") at pquery.c:1058 
#10 0x08193b48 in exec_simple_query (query_string=0x8346e18 "vacuum analyze verbose;") at postgres.c:1017
#11 0x0819570a in PostgresMain (argc=4, argv=0x82ec108, username=0x82ec0e0 "postgres") at postgres.c:3184
#12 0x081716e5 in ServerLoop () at postmaster.c:2862
#13 0x0817235e in PostmasterMain (argc=3, argv=0x82e9d38) at postmaster.c:941
#14 0x0813aab8 in main (argc=3, argv=0x82e9d38) at main.c:268
(gdb) detach
Detaching from program: /usr/local/pgsql/bin/postgres, process 24670
(gdb) quit
dtr2:/var/pgsql/data # ps aux|grep ^postgres
postgres 29479  0.0  0.0 172112  4984 ?        S    Oct07   0:03 /usr/local/pgsql/bin/postmaster -D /var/pgsql/data
postgres 29481  0.0  1.9 172296 165296 ?       S    Oct07   0:12 postgres: writer process
postgres 29482  0.0  0.0   7908  2816 ?        S    Oct07   0:43 postgres: stats buffer process
postgres 29483  0.0  0.0   7228  2028 ?        S    Oct07   0:43 postgres: stats collector process
postgres 30948  0.0  0.0 172968  8124 ?        S    Oct07   0:00 postgres: dtr dtr 127.0.0.1(32794) idle
postgres   744  0.0  0.0   2440  1056 ?        Ss   Oct07   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres   746  0.0  0.0   3200  1004 ?        S    Oct07   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 12664  0.0  0.0   2440  1052 ?        Ss   Oct08   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres 12666  0.0  0.0   3200  1004 ?        S    Oct08   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 24647  0.0  0.0   2440  1052 ?        Ss   Oct09   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres 24649  0.0  0.0   3200  1000 ?        S    Oct09   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres  4273  0.0  0.0   2440  1056 ?        Ss   Oct10   0:00 /bin/sh -c /usr/local/pgsql/bin/psql -c "vacuum
analyzeverbose;" dtr 1> /home/postgres/vacuum-analyze-dtr.out 2>&1 
postgres  4275  0.0  0.0   3200  1004 ?        S    Oct10   0:00 /usr/local/pgsql/bin/psql -c vacuum analyze verbose;
dtr
postgres 14689  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32863) idle
postgres 14690  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32864) idle
postgres 14691  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32865) idle
postgres 14692  0.0  0.0 172864  6944 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32866) idle
postgres 14693  0.0  0.1 173128  8632 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32867) idle
postgres 14694 16.0  1.4 173112 124100 ?       S    11:33  16:22 postgres: dtr dtr 127.0.0.1(32868) idle
postgres 14695  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32869) idle
postgres 14696  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32870) idle
postgres 14697  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32871) idle
postgres 14698  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32872) idle
postgres 14699  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32873) idle
postgres 14700 16.0  1.4 173116 123524 ?       S    11:33  16:22 postgres: dtr dtr 127.0.0.1(32874) idle
postgres 14701  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32875) idle
postgres 14702  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32876) idle
postgres 14703 16.1  1.5 173108 124592 ?       R    11:33  16:24 postgres: dtr dtr 127.0.0.1(32877) UPDATE
postgres 14704 15.9  1.4 173068 124024 ?       S    11:33  16:15 postgres: dtr dtr 127.0.0.1(32878) idle
postgres 14705  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32879) idle
postgres 14706  0.0  0.0 172604  5880 ?        S    11:33   0:00 postgres: dtr dtr 127.0.0.1(32880) idle
postgres 14707 15.9  1.4 173112 123384 ?       S    11:33  16:16 postgres: dtr dtr 127.0.0.1(32881) idle
postgres 14708 15.9  1.4 173108 123244 ?       S    11:33  16:12 postgres: dtr dtr 127.0.0.1(32882) idle
postgres 14961  0.0  0.1 173128  9692 ?        S    12:03   0:00 postgres: dtr dtr 165.219.88.90(54422) idle
postgres 14963  0.0  0.0 172604  5880 ?        S    12:03   0:00 postgres: dtr dtr 165.219.88.90(54424) idle
postgres 14970  0.0  0.1 173080 13440 ?        S    12:04   0:00 postgres: dtr dtr 165.219.88.90(54430) idle
postgres 15021  0.0  0.0 172604  5880 ?        S    12:12   0:00 postgres: dtr dtr 165.219.88.90(54452) idle
postgres  4281  0.0  0.0 173104  7512 ?        S    Oct10   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres   748  0.0  0.0 190008  7544 ?        S    Oct07   0:00 postgres: postgres dtr [local] VACUUM
postgres 12687  0.0  0.0 173636  7572 ?        S    Oct08   0:00 postgres: postgres dtr [local] VACUUM waiting
postgres 24670  0.0  0.0 173636  7888 ?        S    Oct09   0:00 postgres: postgres dtr [local] VACUUM waiting
dtr2:/var/pgsql/data # /usr/local/pgsql/bin/psql postgres postgres
Welcome [snip]

postgres=# select * from pg_locks;  locktype    | database | relation | page | tuple | transactionid | classid | objid
|objsubid | transaction |  pid  |           mode           | granted 

---------------+----------+----------+------+-------+---------------+---------+-------+----------+-------------+-------+--------------------------+---------relation
    |    16385 |     2606 |      |       |               |         |       |          |      840981 |  4281 |
ShareUpdateExclusiveLock| frelation      |    16385 |   780964 |      |       |               |         |       |
  |     1235647 | 14700 | AccessShareLock          | trelation      |    16385 |   780964 |      |       |
|         |       |          |     1235647 | 14700 | RowExclusiveLock         | trelation      |    16385 |     2666 |
   |       |               |         |       |          |      398272 |   748 | RowExclusiveLock         | trelation
 |    16385 |     2666 |      |       |               |         |       |          |      398272 |   748 |
ShareUpdateExclusiveLock| trelation      |    16385 |     2667 |      |       |               |         |       |
  |      398272 |   748 | ShareUpdateExclusiveLock | trelation      |    16385 |    16641 |      |       |
|         |       |          |     1235647 | 14700 | AccessShareLock          | trelation      |    16385 |    16641 |
   |       |               |         |       |          |     1235647 | 14700 | RowExclusiveLock         |
ttransactionid|          |          |      |       |       1235647 |         |       |          |     1235647 | 14700 |
ExclusiveLock           | trelation      |    16385 |     2606 |      |       |               |         |       |
  |      398272 |   748 | ShareUpdateExclusiveLock | trelation      |    10792 |    10341 |      |       |
|         |       |          |     1235648 | 15940 | AccessShareLock          | ttransactionid |          |          |
   |       |        418209 |         |       |          |      418209 | 12687 | ExclusiveLock            | trelation
 |    16385 |     2665 |      |       |               |         |       |          |      398272 |   748 |
ShareUpdateExclusiveLock| trelation      |    16385 |     2606 |      |       |               |         |       |
  |      418209 | 12687 | ShareUpdateExclusiveLock | ftransactionid |          |          |      |       |
1235648|         |       |          |     1235648 | 15940 | ExclusiveLock            | ttransactionid |          |
   |      |       |        398272 |         |       |          |      398272 |   748 | ExclusiveLock            |
trelation     |    16385 |     2664 |      |       |               |         |       |          |      398272 |   748 |
ShareUpdateExclusiveLock| ttransactionid |          |          |      |       |        840981 |         |       |
  |      840981 |  4281 | ExclusiveLock            | trelation      |    16385 |     2606 |      |       |
|         |       |          |      435559 | 24670 | ShareUpdateExclusiveLock | ftransactionid |          |          |
   |       |        435559 |         |       |          |      435559 | 24670 | ExclusiveLock            | t 
(20 rows)
dtr=> \q
Being relatively new to Linux, PostgreSQL, and crontab, it is entirely possible
that is all illuminates nothing but my ignorance regarding how to schedule the
nightly maintenance, but it seemed possible that this could reflect a vacuum
bug.
-Kevin



Re: database vacuum from cron hanging

From
Alvaro Herrera
Date:
Kevin Grittner wrote:
> This may or may not be related to previous threads regarding vacuum problems.
> Following the last thread, we built the development snapshot of Oct 6 with
> --enable-integer-datetimes and --enable-debug.  We have had the autovacuum
> running every ten seconds.  The only table which will meet the autovacuum
> criteria is a table with 72 rows which is frequently updated.  This part was doing
> fine -- keeping the pages to about 20 without any noticable performance hit.

Trivial observation: process 748 is a manually-issued VACUUM (manually,
by cron), it's holding locks other VACUUMs are waiting for, and is
waiting on LockBufferForCleanup.  I guess this means it lost a signal,
or somebody else is holding a pin on the buffer.  If this is the case,
who is it and why isn't it releasing the pin?

Do we have any tools to display the contents of the buffer cache?  We
have pg_buffercache but it'll only display general data, no specifics
(such as who has pins to each buffers).

Maybe GDB could show that info somehow.  I'm unable to provide quick
advice on that, though.

-- 
Alvaro Herrera                        http://www.advogato.org/person/alvherre
"El número de instalaciones de UNIX se ha elevado a 10,
y se espera que este número aumente" (UPM, 1972)


Re: database vacuum from cron hanging

From
Tom Lane
Date:
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Trivial observation: process 748 is a manually-issued VACUUM (manually,
> by cron), it's holding locks other VACUUMs are waiting for, and is
> waiting on LockBufferForCleanup.  I guess this means it lost a signal,
> or somebody else is holding a pin on the buffer.  If this is the case,
> who is it and why isn't it releasing the pin?

Yeah, this is clearly the problem --- the other guys waiting are just
queued up behind this one.

If the system is still in that state, could you reattach to the stuck
process and dop BufferDescriptors[781]
It might be good to dop BufferDescriptors[782]
as well --- I am not sure offhand whether LockBufferForCleanup takes
a 0-based or 1-based index, and in any case it's possible gcc would
have done something weird with the variable contents.  You should
see wait_backend_pid = 748 in the one we want.
        regards, tom lane


Re: database vacuum from cron hanging

From
"Kevin Grittner"
Date:
(gdb) p BufferDescriptors[781]
$1 = {tag = {rnode = {spcNode = 1663, dbNode = 16385, relNode = 2666}, blockNum = 1}, flags = 70, usage_count = 5,
refcount= 4294967294, wait_backend_pid = 748, buf_hdr_lock = 0 '\0', buf_id = 781, freeNext = -2, io_in_progress_lock =
1615,content_lock = 1616} 


>>> Tom Lane <tgl@sss.pgh.pa.us> 10/11/05 4:51 PM >>>
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Trivial observation: process 748 is a manually-issued VACUUM (manually,
> by cron), it's holding locks other VACUUMs are waiting for, and is
> waiting on LockBufferForCleanup.  I guess this means it lost a signal,
> or somebody else is holding a pin on the buffer.  If this is the case,
> who is it and why isn't it releasing the pin?

Yeah, this is clearly the problem --- the other guys waiting are just
queued up behind this one.

If the system is still in that state, could you reattach to the stuck
process and dop BufferDescriptors[781]
It might be good to dop BufferDescriptors[782]
as well --- I am not sure offhand whether LockBufferForCleanup takes
a 0-based or 1-based index, and in any case it's possible gcc would
have done something weird with the variable contents.  You should
see wait_backend_pid = 748 in the one we want.
        regards, tom lane



Re: database vacuum from cron hanging

From
Tom Lane
Date:
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> (gdb) p BufferDescriptors[781]
> $1 = {tag = {rnode = {spcNode = 1663, dbNode = 16385, relNode = 2666}, blockNum = 1}, flags = 70, usage_count = 5,
refcount= 4294967294,
 
>   wait_backend_pid = 748, buf_hdr_lock = 0 '\0', buf_id = 781, freeNext = -2, io_in_progress_lock = 1615,
content_lock= 1616}
 

Whoa.  refcount -2?

Well, now we have an idea what to look for anyway ... and the relNode
says this is pg_constraint_contypid_index.  Again.  There's got to be
some broken code affecting that index in particular ...
        regards, tom lane


Re: database vacuum from cron hanging

From
Tom Lane
Date:
I wrote:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
>> (gdb) p BufferDescriptors[781]
>> $1 = {tag = {rnode = {spcNode = 1663, dbNode = 16385, relNode = 2666}, blockNum = 1}, flags = 70, usage_count = 5,
refcount= 4294967294,
 
>> wait_backend_pid = 748, buf_hdr_lock = 0 '\0', buf_id = 781, freeNext = -2, io_in_progress_lock = 1615, content_lock
=1616}
 

> Whoa.  refcount -2?

BTW, at this point your most helpful move would be to rebuild with
--enable-cassert (keeping --enable-debug) and go back to your current
test mix.  The only place that decrements refcount has
Assert(refcount > 0), so it seems quite likely that you'll soon see
an assertion crash, and then getting a stack trace from that would
probably expose the culprit immediately.  (Make sure you are running
the postmaster under ulimit -c unlimited so that you will get a core
dump file to trace...)
        regards, tom lane


Re: database vacuum from cron hanging

From
Tom Lane
Date:
I wrote:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
>> (gdb) p BufferDescriptors[781]
>> $1 = {tag = {rnode = {spcNode = 1663, dbNode = 16385, relNode = 2666}, blockNum = 1}, flags = 70, usage_count = 5,
refcount= 4294967294,
 
>> wait_backend_pid = 748, buf_hdr_lock = 0 '\0', buf_id = 781, freeNext = -2, io_in_progress_lock = 1615, content_lock
=1616}
 

> Whoa.  refcount -2?

After meditating overnight, I have a theory.  There seem to be two basic
categories of possible explanations for the above state:

1. Some path of control decrements refcount more times than it increments it.
2. Occasionally, an intended increment gets lost.

Yesterday I was thinking in terms of #1, but it really doesn't seem to
fit the observed facts very well.  I don't see a reason why such a bug
would preferentially affect pg_constraint_contypid_index; also it seems
like it would be fairly easily repeatable by many people.  The pin
tracking logic is all internal to individual backends and doesn't look
very vulnerable to, say, timing-related glitches.

On the other hand, it's not hard to concoct a plausible explanation
using #2: suppose that two backends wanting to pin the same buffer at
about the same time pick up the same original value of refcount, add
one, store back.  This is not supposed to happen of course, but maybe
the compiler is optimizing some code in a way that gives this effect
(ie, by reading refcount before the buffer header spinlock has been
acquired).  Now we can account for pg_constraint_contypid_index being
hit: we know you use domains a lot, and that uncached catalog search in
GetDomainConstraints would result in a whole lot of concurrent accesses
to that particular index, so it would be a likely place for such a bug
to manifest.  And we can account for you being the only one seeing it:
this theory makes it compiler- and platform-dependent.

Accordingly: what's the platform exactly? (CPU type, and OS just in
case.)  What compiler was used?  (If gcc, show "gcc -v" output.)
Also please show the output of "pg_config".
        regards, tom lane


Re: database vacuum from cron hanging

From
"Kevin Grittner"
Date:
From an email from the tech who built the box:
The hardware is:

Server:  IBM x346
Model:  8840-42U
CPU:  (2) 3.6 GHz Xeon processors
RAM:  8 GB
RAID 5

OS is SUSE Linux Profession 9.3, fully patched. [as of about a week ago]
SuSE Linux 9.3 (i586) - Kernel \r (\l).
Linux dtr2.wicourts.gov 2.6.11.4-21.9-bigsmp #1 SMP Fri Aug 19 11:58:59 UTC 2005 i686 i686 i386 GNU/Linux

kgrittn@dtr2:~/postgresql-snapshot> gcc -v
Reading specs from /usr/lib/gcc-lib/i586-suse-linux/3.3.5/specs
Configured with: ../configure --enable-threads=posix --prefix=/usr --with-local-prefix=/usr/local
--infodir=/usr/share/info--mandir=/usr/share/man --enable-languages=c,c++,f77,objc,java,ada --disable-checking
--libdir=/usr/lib--enable-libgcj --with-slibdir=/lib --with-system-zlib --enable-shared --enable-__cxa_atexit
i586-suse-linux
Thread model: posix
gcc version 3.3.5 20050117 (prerelease) (SUSE Linux)

I'm not sure what you mean regarding pg_config -- could you clarify?

Your email came through as I was trying to figure out where to find the core dump.  We restarted the server with
cassert,and I find this in the log prior to my attempt to vacuum: 
[2005-10-12 09:09:49.634 CDT] 16603 LOG:  database system was shut down at 2005-10-12 08:57:25 CDT
[2005-10-12 09:09:49.635 CDT] 16603 LOG:  checkpoint record is at 8/A601C904
[2005-10-12 09:09:49.635 CDT] 16603 LOG:  redo record is at 8/A601C904; undo record is at 0/0; shutdown TRUE
[2005-10-12 09:09:49.635 CDT] 16603 LOG:  next transaction ID: 2313003; next OID: 857185
[2005-10-12 09:09:49.635 CDT] 16603 LOG:  next MultiXactId: 1; next MultiXactOffset: 0
[2005-10-12 09:09:49.649 CDT] 16603 LOG:  database system is ready
[2005-10-12 09:09:49.656 CDT] 16603 LOG:  transaction ID wrap limit is 1073743018, limited by database "dtr"
[2005-10-12 09:09:49.684 CDT] 16607 LOG:  autovacuum: processing database "postgres"
[2005-10-12 09:10:00.521 CDT] 16611 LOG:  autovacuum: processing database "dtr"
[2005-10-12 09:10:04.522 CDT] 16618 <dtr dtr 127.0.0.1(33121)> ERROR:  duplicate key violates unique constraint
"DbTranRepositoryPK"
[2005-10-12 09:10:04.522 CDT] 16617 <dtr dtr 127.0.0.1(33120)> ERROR:  duplicate key violates unique constraint
"DbTranRepositoryPK"
[2005-10-12 09:10:04.522 CDT] 16616 <dtr dtr 127.0.0.1(33119)> ERROR:  duplicate key violates unique constraint
"DbTranRepositoryPK"
[2005-10-12 09:10:04.522 CDT] 16619 <dtr dtr 127.0.0.1(33122)> ERROR:  duplicate key violates unique constraint
"DbTranRepositoryPK"
[2005-10-12 09:10:04.522 CDT] 16615 <dtr dtr 127.0.0.1(33118)> ERROR:  duplicate key violates unique constraint
"DbTranRepositoryPK"
[2005-10-12 09:10:05.154 CDT] 16619 <dtr dtr 127.0.0.1(33122)> ERROR:  duplicate key violates unique constraint
"DbTranRepositoryPK"
TRAP: FailedAssertion("!(buf->refcount > 0)", File: "bufmgr.c", Line: 812)
[2005-10-12 09:10:05.695 CDT] 16602 LOG:  server process (PID 16619) was terminated by signal 6
[2005-10-12 09:10:05.695 CDT] 16602 LOG:  terminating any other active server processes
[2005-10-12 09:10:05.695 CDT] 16617 <dtr dtr 127.0.0.1(33120)> WARNING:  terminating connection because of crash of
anotherserver process 
[2005-10-12 09:10:05.695 CDT] 16617 <dtr dtr 127.0.0.1(33120)> DETAIL:  The postmaster has commanded this server
processto roll back the current transaction and exit, because another server process exited abnormally and possibly
corruptedshared memory. 
[2005-10-12 09:10:05.695 CDT] 16617 <dtr dtr 127.0.0.1(33120)> HINT:  In a moment you should be able to reconnect to
thedatabase and repeat your command. 
[2005-10-12 09:10:05.695 CDT] 16618 <dtr dtr 127.0.0.1(33121)> WARNING:  terminating connection because of crash of
anotherserver process 
[2005-10-12 09:10:05.695 CDT] 16618 <dtr dtr 127.0.0.1(33121)> DETAIL:  The postmaster has commanded this server
processto roll back the current transaction and exit, because another server process exited abnormally and possibly
corruptedshared memory. 
[2005-10-12 09:10:05.695 CDT] 16618 <dtr dtr 127.0.0.1(33121)> HINT:  In a moment you should be able to reconnect to
thedatabase and repeat your command. 
[2005-10-12 09:10:05.697 CDT] 16615 <dtr dtr 127.0.0.1(33118)> WARNING:  terminating connection because of crash of
anotherserver process 
[2005-10-12 09:10:05.697 CDT] 16615 <dtr dtr 127.0.0.1(33118)> DETAIL:  The postmaster has commanded this server
processto roll back the current transaction and exit, because another server process exited abnormally and possibly
corruptedshared memory. 
[2005-10-12 09:10:05.697 CDT] 16615 <dtr dtr 127.0.0.1(33118)> HINT:  In a moment you should be able to reconnect to
thedatabase and repeat your command. 
[2005-10-12 09:10:05.698 CDT] 16616 <dtr dtr 127.0.0.1(33119)> WARNING:  terminating connection because of crash of
anotherserver process 
[2005-10-12 09:10:05.698 CDT] 16616 <dtr dtr 127.0.0.1(33119)> DETAIL:  The postmaster has commanded this server
processto roll back the current transaction and exit, because another server process exited abnormally and possibly
corruptedshared memory. 
[2005-10-12 09:10:05.698 CDT] 16616 <dtr dtr 127.0.0.1(33119)> HINT:  In a moment you should be able to reconnect to
thedatabase and repeat your command. 
[2005-10-12 09:10:05.698 CDT] 16614 <dtr dtr 127.0.0.1(33117)> WARNING:  terminating connection because of crash of
anotherserver process 
[2005-10-12 09:10:05.698 CDT] 16614 <dtr dtr 127.0.0.1(33117)> DETAIL:  The postmaster has commanded this server
processto roll back the current transaction and exit, because another server process exited abnormally and possibly
corruptedshared memory. 
[2005-10-12 09:10:05.698 CDT] 16614 <dtr dtr 127.0.0.1(33117)> HINT:  In a moment you should be able to reconnect to
thedatabase and repeat your command. 
[2005-10-12 09:10:05.703 CDT] 16602 LOG:  all server processes terminated; reinitializing
[2005-10-12 09:10:05.719 CDT] 16620 LOG:  database system was interrupted at 2005-10-12 09:09:49 CDT
[2005-10-12 09:10:05.719 CDT] 16620 LOG:  checkpoint record is at 8/A601C904
[2005-10-12 09:10:05.719 CDT] 16620 LOG:  redo record is at 8/A601C904; undo record is at 0/0; shutdown TRUE
[2005-10-12 09:10:05.719 CDT] 16620 LOG:  next transaction ID: 2313003; next OID: 857185
[2005-10-12 09:10:05.719 CDT] 16620 LOG:  next MultiXactId: 1; next MultiXactOffset: 0
[2005-10-12 09:10:05.719 CDT] 16620 LOG:  database system was not properly shut down; automatic recovery in progress
[2005-10-12 09:10:05.719 CDT] 16621 <dtr dtr 127.0.0.1(33123)> FATAL:  the database system is starting up
[2005-10-12 09:10:05.720 CDT] 16620 LOG:  redo starts at 8/A601C948
[2005-10-12 09:10:05.721 CDT] 16622 <dtr dtr 127.0.0.1(33124)> FATAL:  the database system is starting up
[2005-10-12 09:10:05.723 CDT] 16623 <dtr dtr 127.0.0.1(33125)> FATAL:  the database system is starting up
[2005-10-12 09:10:05.725 CDT] 16624 <dtr dtr 127.0.0.1(33126)> FATAL:  the database system is starting up
[2005-10-12 09:10:05.727 CDT] 16625 <dtr dtr 127.0.0.1(33127)> FATAL:  the database system is starting up
[2005-10-12 09:10:05.729 CDT] 16626 <dtr dtr 127.0.0.1(33128)> FATAL:  the database system is starting up
[2005-10-12 09:10:05.734 CDT] 16620 LOG:  record with zero length at 8/A6112FB4
[2005-10-12 09:10:05.734 CDT] 16620 LOG:  redo done at 8/A6112F8C
[2005-10-12 09:10:05.761 CDT] 16620 LOG:  database system is ready
[2005-10-12 09:10:05.762 CDT] 16620 LOG:  transaction ID wrap limit is 1073743018, limited by database "dtr"


>>> Tom Lane <tgl@sss.pgh.pa.us> 10/12/05 9:26 AM >>>
I wrote:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
>> (gdb) p BufferDescriptors[781]
>> $1 = {tag = {rnode = {spcNode = 1663, dbNode = 16385, relNode = 2666}, blockNum = 1}, flags = 70, usage_count = 5,
refcount= 4294967294, 
>> wait_backend_pid = 748, buf_hdr_lock = 0 '\0', buf_id = 781, freeNext = -2, io_in_progress_lock = 1615, content_lock
=1616} 

> Whoa.  refcount -2?

After meditating overnight, I have a theory.  There seem to be two basic
categories of possible explanations for the above state:

1. Some path of control decrements refcount more times than it increments it.
2. Occasionally, an intended increment gets lost.

Yesterday I was thinking in terms of #1, but it really doesn't seem to
fit the observed facts very well.  I don't see a reason why such a bug
would preferentially affect pg_constraint_contypid_index; also it seems
like it would be fairly easily repeatable by many people.  The pin
tracking logic is all internal to individual backends and doesn't look
very vulnerable to, say, timing-related glitches.

On the other hand, it's not hard to concoct a plausible explanation
using #2: suppose that two backends wanting to pin the same buffer at
about the same time pick up the same original value of refcount, add
one, store back.  This is not supposed to happen of course, but maybe
the compiler is optimizing some code in a way that gives this effect
(ie, by reading refcount before the buffer header spinlock has been
acquired).  Now we can account for pg_constraint_contypid_index being
hit: we know you use domains a lot, and that uncached catalog search in
GetDomainConstraints would result in a whole lot of concurrent accesses
to that particular index, so it would be a likely place for such a bug
to manifest.  And we can account for you being the only one seeing it:
this theory makes it compiler- and platform-dependent.

Accordingly: what's the platform exactly? (CPU type, and OS just in
case.)  What compiler was used?  (If gcc, show "gcc -v" output.)
Also please show the output of "pg_config".
        regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate      subscribe-nomail command to
majordomo@postgresql.orgso that your      message can get through to the mailing list cleanly 



Re: database vacuum from cron hanging

From
Alvaro Herrera
Date:
Kevin Grittner wrote:

> I'm not sure what you mean regarding pg_config -- could you clarify?

The output of pg_config --configure

> Your email came through as I was trying to figure out where to find
> the core dump.  We restarted the server with cassert, and I find this
> in the log prior to my attempt to vacuum:

It should be in $PGDATA/core (maybe with some other name depending on
settings)

> TRAP: FailedAssertion("!(buf->refcount > 0)", File: "bufmgr.c", Line: 812)
> [2005-10-12 09:10:05.695 CDT] 16602 LOG:  server process (PID 16619) was terminated by signal 6
> [2005-10-12 09:10:05.695 CDT] 16602 LOG:  terminating any other active server processes

Here is the culprit.

-- 
Alvaro Herrera                                http://www.PlanetPostgreSQL.org
"Always assume the user will do much worse than the stupidest thing
you can imagine."                                (Julien PUYDT)


Re: database vacuum from cron hanging

From
Tom Lane
Date:
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Kevin Grittner wrote:
>> I'm not sure what you mean regarding pg_config -- could you clarify?

> The output of pg_config --configure

Actually I wanted the whole thing, not just --configure (I'm
particularly interested in the CFLAGS setting).

>> Your email came through as I was trying to figure out where to find
>> the core dump.  We restarted the server with cassert, and I find this
>> in the log prior to my attempt to vacuum:

> It should be in $PGDATA/core (maybe with some other name depending on
> settings)

If my theory about a bogus increment code sequence is correct, then the
core dump will not tell us anything very interesting anyway --- the trap
will happen when the slower of the two processes tries to remove its
pin, but that's way after the bug happened.

I'm thinking that the easiest way to confirm or disprove this theory is
to examine the assembly code.  Please do this:1. cd into src/backend/storage/buffer directory of build tree.2. rm
bufmgr.o;make3. Note gcc command issued by make to rebuild bufmgr.o.  Cut and   paste, changing -c to -S and removing
"-obufmgr.o" if present.   Keep all the other switches the same.4. This should produce a file bufmgr.s.  Gzip and send
tome   (off-list please, it's likely to be large and boring)
 
Please also confirm exactly which version of bufmgr.c you are working
with --- the $PostgreSQL line near the head of the file will do.
        regards, tom lane


Re: database vacuum from cron hanging

From
"Kevin Grittner"
Date:
kgrittn@dtr2:~/postgresql-snapshot> /usr/local/pgsql/bin/pg_config
BINDIR = /usr/local/pgsql/bin
DOCDIR = /usr/local/pgsql/doc
INCLUDEDIR = /usr/local/pgsql/include
PKGINCLUDEDIR = /usr/local/pgsql/include
INCLUDEDIR-SERVER = /usr/local/pgsql/include/server
LIBDIR = /usr/local/pgsql/lib
PKGLIBDIR = /usr/local/pgsql/lib
LOCALEDIR =
MANDIR = /usr/local/pgsql/man
SHAREDIR = /usr/local/pgsql/share
SYSCONFDIR = /usr/local/pgsql/etc
PGXS = /usr/local/pgsql/lib/pgxs/src/makefiles/pgxs.mk
CONFIGURE = '--enable-debug' '--enable-cassert'
CC = gcc
CPPFLAGS = -D_GNU_SOURCE
CFLAGS = -O2 -Wall -Wmissing-prototypes -Wpointer-arith -Winline -Wendif-labels -fno-strict-aliasing -g
CFLAGS_SL = -fpic
LDFLAGS = -Wl,-rpath,/usr/local/pgsql/lib
LDFLAGS_SL =
LIBS = -lpgport -lz -lreadline -lcrypt -lresolv -lnsl -ldl -lm
VERSION = PostgreSQL 8.1beta2

This was built from a devel snapshot last Thursday morning:

-rw-r--r--  1 kgrittn users 14354223 2005-10-06 09:56 postgresql-snapshot.tar.gz

kgrittn@dtr2:~/postgresql-snapshot/src/backend/storage/buffer> rm bufmgr.o; make
rm: remove write-protected regular file `bufmgr.o'? yes
gcc -O2 -Wall -Wmissing-prototypes -Wpointer-arith -Winline -Wendif-labels -fno-strict-aliasing -g
-I../../../../src/include-D_GNU_SOURCE   -c -o bufmgr.o bufmgr.c 
/usr/i586-suse-linux/bin/ld -r -o SUBSYS.o buf_table.o buf_init.o bufmgr.o freelist.o localbuf.o
kgrittn@dtr2:~/postgresql-snapshot/src/backend/storage/buffer> grep \$PostgreSQL bufmgr.c*        $PostgreSQL:
pgsql/src/backend/storage/buffer/bufmgr.c,v1.195 2005/08/12 23:13:54 momjian Exp $ 

bufmgr.s file coming in separate (off-list) email.

>>> Tom Lane <tgl@sss.pgh.pa.us> 10/12/05 10:10 AM >>>
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Kevin Grittner wrote:
>> I'm not sure what you mean regarding pg_config -- could you clarify?

> The output of pg_config --configure

Actually I wanted the whole thing, not just --configure (I'm
particularly interested in the CFLAGS setting).

>> Your email came through as I was trying to figure out where to find
>> the core dump.  We restarted the server with cassert, and I find this
>> in the log prior to my attempt to vacuum:

> It should be in $PGDATA/core (maybe with some other name depending on
> settings)

If my theory about a bogus increment code sequence is correct, then the
core dump will not tell us anything very interesting anyway --- the trap
will happen when the slower of the two processes tries to remove its
pin, but that's way after the bug happened.

I'm thinking that the easiest way to confirm or disprove this theory is
to examine the assembly code.  Please do this:1. cd into src/backend/storage/buffer directory of build tree.2. rm
bufmgr.o;make3. Note gcc command issued by make to rebuild bufmgr.o.  Cut and   paste, changing -c to -S and removing
"-obufmgr.o" if present.   Keep all the other switches the same.4. This should produce a file bufmgr.s.  Gzip and send
tome   (off-list please, it's likely to be large and boring) 
Please also confirm exactly which version of bufmgr.c you are working
with --- the $PostgreSQL line near the head of the file will do.
        regards, tom lane



Re: database vacuum from cron hanging

From
Tom Lane
Date:
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> bufmgr.s file coming in separate (off-list) email.

Yup, here is the smoking gun!  This code in PinBuffer
    LockBufHdr_NoHoldoff(buf);    buf->refcount++;    result = (buf->flags & BM_VALID) != 0;
UnlockBufHdr_NoHoldoff(buf);

is translated as
movb    $1, %alcmpb    $0,28(%ebx)    jne    1f        lock            xchgb    %al,28(%ebx)        <-- acquire
spinlock
1: testb    %al, %aljne    .L228            <-- (failure case is out-of-line)
.L221:movl    20(%ebx), %ecx        <-- fetch refcountmovw    16(%ebx), %axincl    %ecx            <-- increment
refcountmovb   $0, 28(%ebx)        <-- release spinlockshrl    %eaxmovl    %ecx, 20(%ebx)        <-- store back
refcountandl   $1, %eaxmovl    %eax, %edi
 

For comparison, gcc 4.0.1 on my Fedora machine produces
movb    $1, %alcmpb    $0,28(%ebx)    jne    1f        lock            xchgb    %al,28(%ebx)        <-- acquire
spinlock
1: testb    %al, %aljne    .L117incl    20(%ebx)        <-- increment refcountmovw    16(%ebx), %axmovb    $0, 28(%ebx)
      <-- release spinlockmovl    %eax, %edishrl    %ediandl    $1, %edimovl    PrivateRefCount, %eax
 

which is safe.

What we probably need to do is insert some "volatile" qualifiers
to force the compiler to behave better.  What happens to the code
if you change PinBuffer to be declared as

static bool
PinBuffer(volatile BufferDesc *buf)

?
        regards, tom lane


Re: database vacuum from cron hanging

From
"Kevin Grittner"
Date:
Declaring it as volatile gives:
       movb    $1, %al       cmpb    $0,28(%ebx)       jne             1f       lock       xchgb   %al,28(%ebx)
1:       testb   %al, %al       jne     .L228
.L221:       movl    20(%ebx), %eax       incl    %eax       movl    %eax, 20(%ebx)       movw    16(%ebx), %ax
movb   $0, 28(%ebx)       shrl    %eax       andl    $1, %eax       movl    %eax, %edi       movl    PrivateRefCount,
%eax


>>> Tom Lane <tgl@sss.pgh.pa.us> 10/12/05 11:00 AM >>>
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> bufmgr.s file coming in separate (off-list) email.

Yup, here is the smoking gun!  This code in PinBuffer
    LockBufHdr_NoHoldoff(buf);    buf->refcount++;    result = (buf->flags & BM_VALID) != 0;
UnlockBufHdr_NoHoldoff(buf);

is translated as
movb    $1, %alcmpb    $0,28(%ebx)    jne    1f        lock            xchgb    %al,28(%ebx)        <-- acquire
spinlock
1: testb    %al, %aljne    .L228            <-- (failure case is out-of-line)
.L221:movl    20(%ebx), %ecx        <-- fetch refcountmovw    16(%ebx), %axincl    %ecx            <-- increment
refcountmovb   $0, 28(%ebx)        <-- release spinlockshrl    %eaxmovl    %ecx, 20(%ebx)        <-- store back
refcountandl   $1, %eaxmovl    %eax, %edi 

For comparison, gcc 4.0.1 on my Fedora machine produces
movb    $1, %alcmpb    $0,28(%ebx)    jne    1f        lock            xchgb    %al,28(%ebx)        <-- acquire
spinlock
1: testb    %al, %aljne    .L117incl    20(%ebx)        <-- increment refcountmovw    16(%ebx), %axmovb    $0, 28(%ebx)
      <-- release spinlockmovl    %eax, %edishrl    %ediandl    $1, %edimovl    PrivateRefCount, %eax 

which is safe.

What we probably need to do is insert some "volatile" qualifiers
to force the compiler to behave better.  What happens to the code
if you change PinBuffer to be declared as

static bool
PinBuffer(volatile BufferDesc *buf)

?
        regards, tom lane



Re: database vacuum from cron hanging

From
Tom Lane
Date:
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> Declaring it as volatile gives:
> [ valid code ]

Good, so at least your compiler's not broken.  I'm busy volatile-izing
all the code in bufmgr.c ... should be able to commit a fix soon.
        regards, tom lane


Re: database vacuum from cron hanging

From
Martijn van Oosterhout
Date:
On Wed, Oct 12, 2005 at 12:25:11PM -0400, Tom Lane wrote:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> > Declaring it as volatile gives:
> > [ valid code ]
>
> Good, so at least your compiler's not broken.  I'm busy volatile-izing
> all the code in bufmgr.c ... should be able to commit a fix soon.

Well, I do notice none of the spinlock code has any memory barriers to
stop gcc moving code across them. I suppose volatile is one way of
solving that... Maybe explicit "don't optimise here" markers would be
worthwhile.
--
Martijn van Oosterhout   <kleptog@svana.org>   http://svana.org/kleptog/
> Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
> tool for doing 5% of the work and then sitting around waiting for someone
> else to do the other 95% so you can sue them.