Date: Thu, 31 Oct 2024 21:20:52 -0700
From: Noah Misch <noah@leadboat.com>
To: Alexander Lakhin <exclusion@gmail.com>,
	Nitin Motiani <nitinmotiani@google.com>,
	Andres Freund <andres@anarazel.de>, pgsql-hackers@postgresql.org
Subject: Re: Inval reliability, especially for inplace updates
Message-ID: <20241101042052.4c.nmisch@google.com>
References: <20240930193350.04.nmisch@google.com>
 <CAH5HC9508Xvz4BVca8OCoDOv7pgHqAf85EqZkWMZ_Q2hAkebzg@mail.gmail.com>
 <20241013004511.9c.nmisch@google.com>
 <CAH5HC94r2ZKy_MhNaPUjn7NHkOFgbyBAgV2jaYSRt35BNWuOAA@mail.gmail.com>
 <CAH5HC95rn4gON8zNrFXFY-Cn4z0NZuDU_1TDwKnafX_25_C0UA@mail.gmail.com>
 <20241024025357.a8.nmisch@google.com>
 <CAH5HC97fbvr63wJO23k6N0YmQh8BK3QE8ch3cQC=dWJJBxaCjw@mail.gmail.com>
 <20241031013924.cd.nmisch@google.com>
 <10ec0bc3-5933-1189-6bb8-5dec4114558e@gmail.com>
 <20241031200139.b4@rfd.leadboat.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20241031200139.b4@rfd.leadboat.com>
User-Agent: Mutt/2.2.12 (2023-09-09)
Archived-At: 
 <https://www.postgresql.org/message-id/20241101042052.4c.nmisch%40google.com>
Precedence: bulk

On Thu, Oct 31, 2024 at 01:01:39PM -0700, Noah Misch wrote:
> On Thu, Oct 31, 2024 at 05:00:02PM +0300, Alexander Lakhin wrote:
> > I've accidentally discovered an incorrect behaviour caused by commit
> > 4eac5a1fa. Running this script:
> 
> Thanks.  This looks important.
> 
> > parallel -j40 --linebuffer --tag .../reproi.sh ::: `seq 40`
> 
> This didn't reproduce it for me, at -j20, -j40, or -j80.  I tested at commit
> fb7e27a.  At what commit(s) does it reproduce for you?  At what commits, if
> any, did your test not reproduce this?

I reproduced this using a tmpfs current working directory.

> > All three autovacuum workers (1143263, 1143320, 1143403) are also waiting
> > for the same buffer lock:
> > #5  0x0000561dd715f1fe in PGSemaphoreLock (sema=0x7fed9a817338) at pg_sema.c:327
> > #6  0x0000561dd722fe02 in LWLockAcquire (lock=0x7fed9ad9b4e4, mode=LW_SHARED) at lwlock.c:1318
> > #7  0x0000561dd71f8423 in LockBuffer (buffer=36, mode=1) at bufmgr.c:4182
> 
> Can you share the full backtrace for the autovacuum workers?

Here, one of the autovacuum workers had the guilty stack trace, appearing at
the end of this message.  heap_inplace_update_and_unlock() calls
CacheInvalidateHeapTupleInplace() while holding BUFFER_LOCK_EXCLUSIVE on a
buffer of pg_class.  CacheInvalidateHeapTupleInplace() may call
CatalogCacheInitializeCache(), which opens the cache's rel.  If there's not a
valid relcache entry for the catcache's rel, we scan pg_class to make a valid
relcache entry.  The ensuing hang makes sense.

Tomorrow, I'll think more about fixes.  Two that might work:

1. Call CacheInvalidateHeapTupleInplace() before locking the buffer.  Each
   time we need to re-find the tuple, discard the previous try's inplace
   invals and redo CacheInvalidateHeapTupleInplace().  That's because
   concurrent activity may have changed cache key fields like relname.

2. Add some function that we call before locking the buffer.  Its charter is
   to ensure PrepareToInvalidateCacheTuple() won't have to call
   CatalogCacheInitializeCache().  I think nothing resets catcache to the
   extent that CatalogCacheInitializeCache() must happen again, so this should
   suffice regardless of concurrent sinval traffic, debug_discard_caches, etc.

What else is worth considering?  Any preferences among those?


#6  0x0000555e8a3c3afc in LWLockAcquire (lock=0x7f1683a65424, mode=LW_SHARED) at lwlock.c:1287
#7  0x0000555e8a08cec8 in heap_prepare_pagescan (sscan=sscan@entry=0x7f168e99ba48) at heapam.c:512
#8  0x0000555e8a08d6f1 in heapgettup_pagemode (scan=scan@entry=0x7f168e99ba48, dir=<optimized out>, nkeys=<optimized out>, key=<optimized out>) at heapam.c:979
#9  0x0000555e8a08dc9e in heap_getnextslot (sscan=0x7f168e99ba48, direction=<optimized out>, slot=0x7f168e9a58c0) at heapam.c:1299
#10 0x0000555e8a0aad3d in table_scan_getnextslot (direction=ForwardScanDirection, slot=<optimized out>, sscan=<optimized out>)
    at ../../../../src/include/access/tableam.h:1080
#11 systable_getnext (sysscan=sysscan@entry=0x7f168e9a79c8) at genam.c:538
#12 0x0000555e8a501391 in ScanPgRelation (targetRelId=<optimized out>, indexOK=false, force_non_historic=force_non_historic@entry=false) at relcache.c:388
#13 0x0000555e8a507ea4 in RelationReloadIndexInfo (relation=0x7f168f1b8808) at relcache.c:2272
#14 RelationRebuildRelation (relation=0x7f168f1b8808) at relcache.c:2573
#15 0x0000555e8a5083e5 in RelationFlushRelation (relation=0x7f168f1b8808) at relcache.c:2848
#16 RelationCacheInvalidateEntry (relationId=<optimized out>) at relcache.c:2910
#17 0x0000555e8a4fafaf in LocalExecuteInvalidationMessage (msg=0x7ffec99ff8a0) at inval.c:795
#18 0x0000555e8a3b711a in ReceiveSharedInvalidMessages (invalFunction=invalFunction@entry=0x555e8a4faf10 <LocalExecuteInvalidationMessage>, 
    resetFunction=resetFunction@entry=0x555e8a4fa650 <InvalidateSystemCaches>) at sinval.c:88
#19 0x0000555e8a4fa677 in AcceptInvalidationMessages () at inval.c:865
#20 0x0000555e8a3bc809 in LockRelationOid (relid=1259, lockmode=1) at lmgr.c:135
#21 0x0000555e8a05155d in relation_open (relationId=relationId@entry=1259, lockmode=lockmode@entry=1) at relation.c:55
#22 0x0000555e8a0dd809 in table_open (relationId=relationId@entry=1259, lockmode=lockmode@entry=1) at table.c:44
#23 0x0000555e8a501359 in ScanPgRelation (targetRelId=<optimized out>, indexOK=indexOK@entry=true, force_non_historic=force_non_historic@entry=false)
    at relcache.c:371
#24 0x0000555e8a507f9a in RelationReloadNailed (relation=0x7f168f1738c8) at relcache.c:2380
#25 RelationRebuildRelation (relation=0x7f168f1738c8) at relcache.c:2579
#26 0x0000555e8a5083e5 in RelationFlushRelation (relation=0x7f168f1738c8) at relcache.c:2848
#27 RelationCacheInvalidateEntry (relationId=<optimized out>) at relcache.c:2910
#28 0x0000555e8a4fafaf in LocalExecuteInvalidationMessage (msg=0x7ffec99ffc80) at inval.c:795
#29 0x0000555e8a3b71aa in ReceiveSharedInvalidMessages (invalFunction=invalFunction@entry=0x555e8a4faf10 <LocalExecuteInvalidationMessage>, 
    resetFunction=resetFunction@entry=0x555e8a4fa650 <InvalidateSystemCaches>) at sinval.c:118
#30 0x0000555e8a4fa677 in AcceptInvalidationMessages () at inval.c:865
#31 0x0000555e8a3bc809 in LockRelationOid (relid=1259, lockmode=1) at lmgr.c:135
#32 0x0000555e8a05155d in relation_open (relationId=1259, lockmode=lockmode@entry=1) at relation.c:55
#33 0x0000555e8a0dd809 in table_open (relationId=<optimized out>, lockmode=lockmode@entry=1) at table.c:44
#34 0x0000555e8a4f7211 in CatalogCacheInitializeCache (cache=cache@entry=0x555eb26d2180) at catcache.c:1045
#35 0x0000555e8a4f9a68 in PrepareToInvalidateCacheTuple (relation=relation@entry=0x7f168f1738c8, tuple=tuple@entry=0x7f168e9a74e8, newtuple=newtuple@entry=0x0, 
    function=function@entry=0x555e8a4fa220 <RegisterCatcacheInvalidation>, context=context@entry=0x7f168e9a7428) at catcache.c:2326
#36 0x0000555e8a4fa500 in CacheInvalidateHeapTupleCommon (relation=relation@entry=0x7f168f1738c8, tuple=tuple@entry=0x7f168e9a74e8, newtuple=newtuple@entry=0x0, 
    prepare_callback=prepare_callback@entry=0x555e8a4fa320 <PrepareInplaceInvalidationState>) at inval.c:1391
#37 0x0000555e8a4fabcb in CacheInvalidateHeapTupleCommon (prepare_callback=0x555e8a4fa320 <PrepareInplaceInvalidationState>, newtuple=newtuple@entry=0x0, 
    tuple=tuple@entry=0x7f168e9a74e8, relation=relation@entry=0x7f168f1738c8) at inval.c:1504
#38 0x0000555e8a094f7c in heap_inplace_update_and_unlock (relation=0x7f168f1738c8, oldtup=0x555eb277ea58, tuple=0x7f168e9a74e8, buffer=3) at heapam.c:6354
#39 0x0000555e8a0ab35a in systable_inplace_update_finish (state=0x7f168e9a72c8, tuple=<optimized out>) at genam.c:891
#40 0x0000555e8a1fbdc4 in vac_update_relstats (relation=relation@entry=0x7f168f1beae8, num_pages=num_pages@entry=19, num_tuples=<optimized out>, 
    num_all_visible_pages=<optimized out>, hasindex=hasindex@entry=true, frozenxid=frozenxid@entry=0, minmulti=minmulti@entry=0, frozenxid_updated=0x0, 
    minmulti_updated=0x0, in_outer_xact=false) at vacuum.c:1545
#41 0x0000555e8a18c97c in do_analyze_rel (onerel=onerel@entry=0x7f168f1beae8, params=params@entry=0x555eb272e2e4, va_cols=va_cols@entry=0x0, 
    acquirefunc=<optimized out>, relpages=19, inh=inh@entry=false, in_outer_xact=false, elevel=13) at analyze.c:643
#42 0x0000555e8a18e122 in analyze_rel (relid=<optimized out>, relation=<optimized out>, params=params@entry=0x555eb272e2e4, va_cols=0x0, 
    in_outer_xact=<optimized out>, bstrategy=bstrategy@entry=0x555eb2741238) at analyze.c:249
#43 0x0000555e8a1fc883 in vacuum (relations=0x555eb274b370, relations@entry=0x555eb2749390, params=params@entry=0x555eb272e2e4, 
    bstrategy=bstrategy@entry=0x555eb2741238, vac_context=vac_context@entry=0x555eb274b220, isTopLevel=isTopLevel@entry=true) at vacuum.c:635
#44 0x0000555e8a330e69 in autovacuum_do_vac_analyze (bstrategy=<optimized out>, tab=<optimized out>) at autovacuum.c:3108
#45 do_autovacuum () at autovacuum.c:2425
#46 0x0000555e8a33132f in AutoVacWorkerMain (startup_data=<optimized out>, startup_data_len=<optimized out>) at autovacuum.c:1571
...
(gdb) p num_held_lwlocks
$2 = 1