Re: LWLock deadlock and gdb advice

Jeff Janes wrote:

> I've gotten the LWLock deadlock again.  User backend 24841 holds the
> WALInsertLocks 7 and is blocked attempting to acquire 6 .  So it seems to
> be violating the lock ordering rules (although I don't see that rule
> spelled out in xlog.c)

Hmm, interesting -- pg_stat_statement is trying to re-do an operation
that involves updating a GIN index, while WAL-logging for the original
update is still ongoing, it seems.


> #0  0x0000003dcb6eaf27 in semop () from /lib64/libc.so.6
> #1  0x0000000000671aef in PGSemaphoreLock (sema=0x7f70e9e2a108) at
> pg_sema.c:387
> #2  0x00000000006d79ac in LWLockWaitForVar (lock=0x7f70e13df000,
> valptr=0x7f70e13df028, oldval=0, newval=0x7fffb33cbd48) at lwlock.c:1406
> #3  0x00000000004ee006 in WaitXLogInsertionsToFinish (upto=41590734848) at
> xlog.c:1576
> #4  0x00000000004ee94b in AdvanceXLInsertBuffer (upto=41594920960,
> opportunistic=<value optimized out>) at xlog.c:1888
> #5  0x00000000004f3c42 in GetXLogBuffer (ptr=41594920960) at xlog.c:1669
> #6  0x00000000004f40e7 in CopyXLogRecordToWAL (rdata=0x19bc920,
> fpw_lsn=<value optimized out>) at xlog.c:1313
> #7  XLogInsertRecord (rdata=0x19bc920, fpw_lsn=<value optimized out>) at
> xlog.c:1008
> #8  0x00000000004f7c6c in XLogInsert (rmid=13 '\r', info=32 ' ') at
> xloginsert.c:453
> #9  0x000000000047e210 in ginPlaceToPage (btree=0x7fffb33cc070,
> stack=0x1a5bfe0, insertdata=<value optimized out>, updateblkno=<value
> optimized out>, childbuf=0, buildStats=0x0)
>     at ginbtree.c:418
> #10 0x000000000047f50d in ginInsertValue (btree=0x7fffb33cc070,
> stack=0x1a5bfe0, insertdata=0x7fffb33cc0f0, buildStats=0x0) at
> ginbtree.c:748
> #11 0x0000000000475deb in ginEntryInsert (ginstate=0x7fffb33cc470,
> attnum=5544, key=1, category=<value optimized out>, items=0x7f70e10d9140,
> nitem=51, buildStats=0x0)
>     at gininsert.c:234
> #12 0x000000000048602c in ginInsertCleanup (ginstate=0x7fffb33cc470,
> vac_delay=<value optimized out>, stats=0x0) at ginfast.c:843
> #13 0x00000000004871b9 in ginHeapTupleFastInsert (ginstate=0x7fffb33cc470,
> collector=<value optimized out>) at ginfast.c:436
> #14 0x000000000047625a in gininsert (fcinfo=<value optimized out>) at
> gininsert.c:531
> #15 0x00000000007dc483 in FunctionCall6Coll (flinfo=<value optimized out>,
> collation=<value optimized out>, arg1=<value optimized out>, arg2=<value
> optimized out>,
>     arg3=<value optimized out>, arg4=<value optimized out>,
> arg5=140122789534360, arg6=0) at fmgr.c:1436
> #16 0x00000000004b2247 in index_insert (indexRelation=0x7f70e1190e60,
> values=0x7fffb33cef50, isnull=0x7fffb33cf050 "", heap_t_ctid=0x1a4a794,
> heapRelation=0x7f70e1185a98,
>     checkUnique=UNIQUE_CHECK_NO) at indexam.c:226
> #17 0x00000000005d2e67 in ExecInsertIndexTuples (slot=0x1a497f0,
> tupleid=0x1a4a794, estate=0x1a40768, noDupErr=0 '\000', specConflict=0x0,
> arbiterIndexes=0x0)
>     at execIndexing.c:384
> #18 0x00000000005f0161 in ExecUpdate (tupleid=0x7fffb33cf250, oldtuple=0x0,
> slot=0x1a497f0, planSlot=0x1a42498, epqstate=0x1a40a70, estate=0x1a40768,
> canSetTag=1 '\001')
>     at nodeModifyTable.c:978
> #19 0x00000000005f0b2a in ExecModifyTable (node=0x1a409d0) at
> nodeModifyTable.c:1436
> #20 0x00000000005d6cc8 in ExecProcNode (node=0x1a409d0) at
> execProcnode.c:389
> #21 0x00000000005d5402 in ExecutePlan (queryDesc=0x1a2b220,
> direction=<value optimized out>, count=0) at execMain.c:1549
> #22 standard_ExecutorRun (queryDesc=0x1a2b220, direction=<value optimized
> out>, count=0) at execMain.c:337
> #23 0x00007f70ea39af3b in pgss_ExecutorRun (queryDesc=0x1a2b220,
> direction=ForwardScanDirection, count=0) at pg_stat_statements.c:881
> #24 0x00000000006ea38f in ProcessQuery (plan=0x1a2b3d8,
> sourceText=0x1a2af68 "update foo set count=count+1 where text_array @> $1",
> params=0x1a2afe8, dest=<value optimized out>,
>     completionTag=0x7fffb33cf660 "") at pquery.c:185
> #25 0x00000000006ea5ec in PortalRunMulti (portal=0x19a6128, isTopLevel=1
> '\001', dest=0xc55020, altdest=0xc55020, completionTag=0x7fffb33cf660 "")
> at pquery.c:1279
> #26 0x00000000006eadb3 in PortalRun (portal=0x19a6128,
> count=9223372036854775807, isTopLevel=1 '\001', dest=0x1990630,
> altdest=0x1990630, completionTag=0x7fffb33cf660 "")
>     at pquery.c:816
> #27 0x00000000006e6ffb in exec_execute_message (portal_name=0x1990218 "",
> max_rows=9223372036854775807) at postgres.c:1988
> #28 0x00000000006e8c15 in PostgresMain (argc=<value optimized out>,
> argv=<value optimized out>, dbname=0x19a3210 "jjanes", username=<value
> optimized out>) at postgres.c:4088
> #29 0x00000000006855dd in BackendRun (argc=<value optimized out>,
> argv=<value optimized out>) at postmaster.c:4159
> #30 BackendStartup (argc=<value optimized out>, argv=<value optimized out>)
> at postmaster.c:3835
> #31 ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at
> postmaster.c:1609
> #32 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>)
> at postmaster.c:1254
> #33 0x0000000000610ab0 in main (argc=4, argv=0x1976cf0) at main.c:221


-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services