BUG #3883: Autovacuum deadlock with truncate? - Mailing list pgsql-bugs

The following bug has been logged online:

Bug reference:      3883
Logged by:          Steven Flatt
Email address:      steven.flatt@gmail.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