BUG #3883: Autovacuum deadlock with truncate?

The following bug has been logged online:

Bug reference: 3883
Logged by: Steven Flatt
Email address: steven(dot)flatt(at)gmail(dot)com
PostgreSQL version: 8.2.4
Operating system: FreeBSD 6.1
Description: Autovacuum deadlock with truncate?
Details:

This isn't a postgres deadlock per se, but the end result is that two
postgres backends are stuck, each waiting on a PGSemaphoreLock that the
other presumably has. The processes have been stuck for hours.

First process is the postgres autovacuum.
Second process is a PLpgSQL function which is intended to "clean tables".
It goes through a list of tables and truncates them if they have any data.
I realize that it generally doesn't make a great deal of sense to truncate
data so soon after being modified that the data hasn't even been
vacuumed/analyzed, but this happened in a test environment and we'd like to
understand the root cause.

pg_locks info and gdb backtraces follow:

-------------------------------------------------------

pid 35775 (autovacuum)

=# select pid,relation,mode,granted from pg_locks where pid = 35775;
pid | relation | mode | granted
-------+----------+--------------------------+---------
35775 | 16783 | ShareUpdateExclusiveLock | t
35775 | 16788 | RowExclusiveLock | t
35775 | 16790 | RowExclusiveLock | t
35775 | 16791 | RowExclusiveLock | t
35775 | | ExclusiveLock | t
(5 rows)

(gdb) bt
#0 0x6854a5b7 in semop () from /lib/libc.so.6
#1 0x081c7b4f in PGSemaphoreLock (sema=0x86adf888, interruptOK=1 '\001')
at pg_sema.c:411
#2 0x081f50f1 in ProcWaitForSignal () at proc.c:1075
#3 0x081e78e3 in LockBufferForCleanup (buffer=14408) at bufmgr.c:1926
#4 0x081541c2 in lazy_vacuum_heap (onerel=0x86a8c08,
vacrelstats=0x8668170)
at vacuumlazy.c:552
#5 0x08153fa0 in lazy_scan_heap (onerel=0x86a8c08, vacrelstats=0x8668170,
Irel=0x8668158, nindexes=3) at vacuumlazy.c:482
#6 0x08153722 in lazy_vacuum_rel (onerel=0x86a8c08, vacstmt=0x86c6be0)
at vacuumlazy.c:164
#7 0x0814f623 in vacuum_rel (relid=16783, vacstmt=0x86c6be0,
expected_relkind=114 'r') at vacuum.c:1098
#8 0x0814eb10 in vacuum (vacstmt=0x86c6be0, relids=0x86c6d18) at
vacuum.c:397
#9 0x081c9d57 in autovacuum_do_vac_analyze (relid=16783, dovacuum=1
'\001',
doanalyze=1 '\001', freeze_min_age=100000000) at autovacuum.c:912
#10 0x081c97e4 in do_autovacuum (dbentry=0x840dc08) at autovacuum.c:659
#11 0x081c92c1 in AutoVacMain (argc=0, argv=0x0) at autovacuum.c:433
#12 0x081c8f3a in autovac_start () at autovacuum.c:178
#13 0x081cf01a in ServerLoop () at postmaster.c:1249
#14 0x081ce916 in PostmasterMain (argc=3, argv=0x9fbfed40) at
postmaster.c:963
#15 0x0817fef0 in main (argc=3, argv=0x9fbfed40) at main.c:188

-------------------------------------------------------

pid 6869 (function to clean tables)

=# select pid,relation,mode,granted from pg_locks where pid = 6869 and not
granted;
pid | relation | mode | granted
------+----------+---------------------+---------
6869 | 16783 | AccessExclusiveLock | f

(gdb) bt
#0 0x6854a5b7 in semop () from /lib/libc.so.6
#1 0x081c7b4f in PGSemaphoreLock (sema=0x86ae0890, interruptOK=1 '\001')
at pg_sema.c:411
#2 0x081f4e29 in ProcSleep (locallock=0x8f5e160,
lockMethodTable=0x8332324)
at proc.c:829
#3 0x081f2660 in WaitOnLock (locallock=0x8f5e160, owner=0x9965db8)
at lock.c:1140
#4 0x081f2120 in LockAcquire (locktag=0x9fbfdc70, lockmode=8,
sessionLock=0 '\0', dontWait=0 '\0') at lock.c:792
#5 0x081f0eb4 in LockRelationOid (relid=16783, lockmode=8) at lmgr.c:81
#6 0x08091b6e in relation_open (relationId=16783, lockmode=8) at
heapam.c:694
#7 0x08091db2 in relation_openrv (relation=0xbdf9110, lockmode=8)
at heapam.c:821
#8 0x08091ef4 in heap_openrv (relation=0xbdf9110, lockmode=8) at
heapam.c:891
#9 0x08135610 in ExecuteTruncate (stmt=0xbdf9160) at tablecmds.c:549
#10 0x08202da1 in ProcessUtility (parsetree=0xbdf9160, params=0x0,
dest=0x835b4c0, completionTag=0x0) at utility.c:626
#11 0x08175868 in _SPI_execute_plan (plan=0x9fbfde80, Values=0x0,
Nulls=0x0,
snapshot=0x0, crosscheck_snapshot=0x0, read_only=0 '\0', tcount=0)
at spi.c:1496
#12 0x0817374d in SPI_execute (
src=0x8a1db18 "TRUNCATE foo", read_only=0 '\0',
tcount=0) at spi.c:316
#13 0x87d23df1 in exec_stmt_dynexecute (estate=0x9fbfe270, stmt=0x84e01b0)
at pl_exec.c:2561
#14 0x87d21ba2 in exec_stmt (estate=0x9fbfe270, stmt=0x84e01b0)
at pl_exec.c:1212
#15 0x87d2196d in exec_stmts (estate=0x9fbfe270, stmts=0x84e0038)
at pl_exec.c:1123
#16 0x87d2450d in exec_stmt_dynfors (estate=0x9fbfe270, stmt=0x84dfde0)
at pl_exec.c:2793
#17 0x87d21bbb in exec_stmt (estate=0x9fbfe270, stmt=0x84dfde0)
at pl_exec.c:1216
#18 0x87d2196d in exec_stmts (estate=0x9fbfe270, stmts=0x84dffb0)
at pl_exec.c:1123
#19 0x87d226e6 in exec_stmt_fors (estate=0x9fbfe270, stmt=0x84df9e0)
at pl_exec.c:1694
#20 0x87d21b0c in exec_stmt (estate=0x9fbfe270, stmt=0x84df9e0)
at pl_exec.c:1188
#21 0x87d2196d in exec_stmts (estate=0x9fbfe270, stmts=0x84dfed0)
at pl_exec.c:1123
#22 0x87d21e85 in exec_stmt_if (estate=0x9fbfe270, stmt=0x84e0760)
at pl_exec.c:1346
#23 0x87d21aa8 in exec_stmt (estate=0x9fbfe270, stmt=0x84e0760)
at pl_exec.c:1172
#24 0x87d2196d in exec_stmts (estate=0x9fbfe270, stmts=0x84dff78)
at pl_exec.c:1123
#25 0x87d217ec in exec_stmt_block (estate=0x9fbfe270, block=0x84e1db0)
at pl_exec.c:1068
#26 0x87d20167 in plpgsql_exec_function (func=0x84c22f8, fcinfo=0x9fbfe3b0)
at pl_exec.c:286
#27 0x87d1c2c3 in plpgsql_call_handler (fcinfo=0x9fbfe3b0) at
pl_handler.c:95
#28 0x0815d00a in ExecMakeFunctionResult (fcache=0x87982b8,
econtext=0x8798230, isNull=0x8798840 "", isDone=0x8798898)
at execQual.c:1269
#29 0x0815d860 in ExecEvalFunc (fcache=0x87982b8, econtext=0x8798230,
isNull=0x8798840 "", isDone=0x8798898) at execQual.c:1671
#30 0x08161ad2 in ExecTargetList (targetlist=0x8798710, econtext=0x8798230,
values=0x8798830, isnull=0x8798840 "", itemIsDone=0x8798898,
isDone=0x9fbfe694) at execQual.c:4119
#31 0x08161ec4 in ExecProject (projInfo=0x8798850, isDone=0x9fbfe694)
at execQual.c:4320
#32 0x0816e944 in ExecResult (node=0x87981a8) at nodeResult.c:157
#33 0x0815aef9 in ExecProcNode (node=0x87981a8) at execProcnode.c:334
#34 0x08158f26 in ExecutePlan (estate=0x8798018, planstate=0x87981a8,
operation=CMD_SELECT, numberTuples=0, direction=ForwardScanDirection,
dest=0x84524d8) at execMain.c:1082
#35 0x081580e7 in ExecutorRun (queryDesc=0x8a35040,
direction=ForwardScanDirection, count=0) at execMain.c:241
#36 0x08201509 in PortalRunSelect (portal=0x8497018, forward=1 '\001',
count=0, dest=0x84524d8) at pquery.c:831
#37 0x08201247 in PortalRun (portal=0x8497018, count=2147483647,
dest=0x84524d8, altdest=0x84524d8, completionTag=0x9fbfe900 "")
at pquery.c:656
#38 0x081fc69d in exec_simple_query (
query_string=0x8451018 "SELECT fn_clean_tables()")
at postgres.c:939
#39 0x081ffe18 in PostgresMain (argc=4, argv=0x83b3448,
username=0x83b3428 "pgsql") at postgres.c:3424
#40 0x081d1ace in BackendRun (port=0x83af000) at postmaster.c:2931
#41 0x081d1098 in BackendStartup (port=0x83af000) at postmaster.c:2558
#42 0x081cef3b in ServerLoop () at postmaster.c:1211
#43 0x081ce916 in PostmasterMain (argc=3, argv=0x9fbfed40) at
postmaster.c:963
#44 0x0817fef0 in main (argc=3, argv=0x9fbfed40) at main.c:188