Thread: database vacuum from cron hanging
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
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)
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
(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
"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
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
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
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
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)
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
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
"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
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
"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
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.