Re: Backend stuck in tirigger.c:afterTriggerInvokeEvents forever

Andres,

Thanks for taking a look at this.

Here is a sample of pg_waldump while the problem is occurring:

rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D37435A8, prev A/D37415A0, desc: INSERT off 40 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3743668, prev A/D37435A8, desc: INSERT_LEAF off 96, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 54/ 54, tx: 35961, lsn:
A/D37436B0, prev A/D3743668, desc: LOCK off 41: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1792
rmgr: Heap len (rec/tot): 194/ 194, tx: 35961, lsn:
A/D37436E8, prev A/D37436B0, desc: INSERT off 41 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D37437B0, prev A/D37436E8, desc: INSERT_LEAF off 93, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8175, tx: 35961, lsn:
A/D37437F8, prev A/D37437B0, desc: LOCK off 33: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1799 FPW
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D3745800, prev A/D37437F8, desc: INSERT off 42 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D37458C0, prev A/D3745800, desc: INSERT_LEAF off 95, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Standby len (rec/tot): 66/ 66, tx: 0, lsn:
A/D3745908, prev A/D37458C0, desc: LOCK xid 35961 db 99095 rel 125491
xid 35961 db 99095 rel 125485 xid 35961 db 99095 rel 125490
rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn:
A/D3745950, prev A/D3745908, desc: RUNNING_XACTS nextXid 35962
latestCompletedXid 35960 oldestRunningXid 35961; 1 xacts: 35961
rmgr: Heap len (rec/tot): 59/ 8175, tx: 35961, lsn:
A/D3745988, prev A/D3745950, desc: LOCK off 4: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1772 FPW
rmgr: Heap len (rec/tot): 194/ 194, tx: 35961, lsn:
A/D3747990, prev A/D3745988, desc: INSERT off 43 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3747A58, prev A/D3747990, desc: INSERT_LEAF off 89, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 54/ 54, tx: 35961, lsn:
A/D3747AA0, prev A/D3747A58, desc: LOCK off 3: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1799
rmgr: Heap len (rec/tot): 193/ 193, tx: 35961, lsn:
A/D3747AD8, prev A/D3747AA0, desc: INSERT off 44 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3747BA0, prev A/D3747AD8, desc: INSERT_LEAF off 96, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 54/ 54, tx: 35961, lsn:
A/D3747BE8, prev A/D3747BA0, desc: LOCK off 16: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1799
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D3747C20, prev A/D3747BE8, desc: INSERT off 45 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3747CE0, prev A/D3747C20, desc: INSERT_LEAF off 97, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8167, tx: 35961, lsn:
A/D3747D28, prev A/D3747CE0, desc: LOCK off 16: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1801 FPW
rmgr: Heap len (rec/tot): 186/ 186, tx: 35961, lsn:
A/D3749D28, prev A/D3747D28, desc: INSERT off 46 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3749DE8, prev A/D3749D28, desc: INSERT_LEAF off 99, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Standby len (rec/tot): 66/ 66, tx: 0, lsn:
A/D3749E30, prev A/D3749DE8, desc: LOCK xid 35961 db 99095 rel 125491
xid 35961 db 99095 rel 125485 xid 35961 db 99095 rel 125490
rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn:
A/D3749E78, prev A/D3749E30, desc: RUNNING_XACTS nextXid 35962
latestCompletedXid 35960 oldestRunningXid 35961; 1 xacts: 35961
rmgr: Heap len (rec/tot): 59/ 8191, tx: 35961, lsn:
A/D3749EB0, prev A/D3749E78, desc: LOCK off 13: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1802 FPW
rmgr: Heap len (rec/tot): 190/ 190, tx: 35961, lsn:
A/D374BEC8, prev A/D3749EB0, desc: INSERT off 47 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D374BF88, prev A/D374BEC8, desc: INSERT_LEAF off 100, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8239, tx: 35961, lsn:
A/D374BFD0, prev A/D374BF88, desc: LOCK off 54: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104057 blk 1 FPW
rmgr: Heap len (rec/tot): 59/ 8167, tx: 35961, lsn:
A/D374E030, prev A/D374BFD0, desc: LOCK off 41: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1822 FPW
rmgr: Heap len (rec/tot): 178/ 178, tx: 35961, lsn:
A/D3750030, prev A/D374E030, desc: INSERT off 48 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D37500E8, prev A/D3750030, desc: INSERT_LEAF off 104, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Standby len (rec/tot): 66/ 66, tx: 0, lsn:
A/D3750130, prev A/D37500E8, desc: LOCK xid 35961 db 99095 rel 125491
xid 35961 db 99095 rel 125485 xid 35961 db 99095 rel 125490
rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn:
A/D3750178, prev A/D3750130, desc: RUNNING_XACTS nextXid 35962
latestCompletedXid 35960 oldestRunningXid 35961; 1 xacts: 35961
rmgr: Heap len (rec/tot): 59/ 8199, tx: 35961, lsn:
A/D37501B0, prev A/D3750178, desc: LOCK off 42: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1826 FPW
rmgr: Heap len (rec/tot): 194/ 194, tx: 35961, lsn:
A/D37521D0, prev A/D37501B0, desc: INSERT off 49 flags 0x00, blkref
#0: rel 1663/99095/104041 blk 8
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3752298, prev A/D37521D0, desc: INSERT_LEAF off 106, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8175, tx: 35961, lsn:
A/D37522E0, prev A/D3752298, desc: LOCK off 41: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1833 FPW
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D37542E8, prev A/D37522E0, desc: INSERT+INIT off 1 flags 0x00,
blkref #0: rel 1663/99095/104041 blk 9
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D37543A8, prev A/D37542E8, desc: INSERT_LEAF off 108, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8183, tx: 35961, lsn:
A/D37543F0, prev A/D37543A8, desc: LOCK off 4: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1834 FPW
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D3756400, prev A/D37543F0, desc: INSERT off 2 flags 0x00, blkref #0:
rel 1663/99095/104041 blk 9
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D37564C0, prev A/D3756400, desc: INSERT_LEAF off 109, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 54/ 54, tx: 35961, lsn:
A/D3756508, prev A/D37564C0, desc: LOCK off 7: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1834
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D3756540, prev A/D3756508, desc: INSERT off 3 flags 0x00, blkref #0:
rel 1663/99095/104041 blk 9
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D3756600, prev A/D3756540, desc: INSERT_LEAF off 110, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Standby len (rec/tot): 66/ 66, tx: 0, lsn:
A/D3756648, prev A/D3756600, desc: LOCK xid 35961 db 99095 rel 125491
xid 35961 db 99095 rel 125485 xid 35961 db 99095 rel 125490
rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn:
A/D3756690, prev A/D3756648, desc: RUNNING_XACTS nextXid 35962
latestCompletedXid 35960 oldestRunningXid 35961; 1 xacts: 35961
rmgr: Heap len (rec/tot): 59/ 8191, tx: 35961, lsn:
A/D37566C8, prev A/D3756690, desc: LOCK off 27: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1549 FPW
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D37586E0, prev A/D37566C8, desc: INSERT off 4 flags 0x00, blkref #0:
rel 1663/99095/104041 blk 9
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D37587A0, prev A/D37586E0, desc: INSERT_LEAF off 69, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8191, tx: 35961, lsn:
A/D37587E8, prev A/D37587A0, desc: LOCK off 30: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1554 FPW
rmgr: Heap len (rec/tot): 185/ 185, tx: 35961, lsn:
A/D375A800, prev A/D37587E8, desc: INSERT off 5 flags 0x00, blkref #0:
rel 1663/99095/104041 blk 9
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D375A8C0, prev A/D375A800, desc: INSERT_LEAF off 70, blkref #0: rel
1663/99095/113582 blk 2
rmgr: Heap len (rec/tot): 59/ 8175, tx: 35961, lsn:
A/D375A908, prev A/D375A8C0, desc: LOCK off 46: xid 35961: flags 0x00
LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/99095/104336 blk 1555 FPW
rmgr: Heap len (rec/tot): 199/ 199, tx: 35961, lsn:
A/D375C910, prev A/D375A908, desc: INSERT off 6 flags 0x00, blkref #0:
rel 1663/99095/104041 blk 9
rmgr: Btree len (rec/tot): 72/ 72, tx: 35961, lsn:
A/D375C9D8, prev A/D375C910, desc: INSERT_LEAF off 71, blkref #0: rel
1663/99095/113582 blk 2

On Wed, Apr 22, 2020 at 8:39 PM Andres Freund <andres(at)anarazel(dot)de> wrote:
>
> Hi,
>
> On 2020-04-21 11:19:35 -0400, Alvaro Herrera wrote:
> > On 2020-Apr-21, Tom Lane wrote:
> >
> > > A variant of that theory is that foreign key trigger firings are being
> > > skipped in one case but not the other; but offhand I think those
> > > optimizations only apply to update/delete cases not inserts. Anyway
> > > that still requires some assumptions about moving parts that you
> > > haven't shown us.
> >
> > I wonder if there are any funny interactions between trigger tuple
> > acquisition and the ON CONFLICT stuff. The only thing that occurs to me
> > to explain the fact that it only fails with the two stmts in the DO
> > block is that the second insert can see rows as inserted by the same
> > transaction.
>
> I wonder if there's potentially some issue with the wrong snapshot being
> used for the different statements...
>
> > I would start by taking a few dozen backtraces and comparing them to see
> > if any progress is being made.
>
> It could also be informative to look at the walstream with pg_waldump
> while the problem is occuring. Would tell us about row locks acquired
> during on conflict / trigger handling etc.
>
> > The fact that this reproduces in 11.2 would seem to discard theories
> > about tuple table slot changes and table AM.
>
> Phew ;)
>
> Greetings,
>
> Andres Freund