On Mon, Sep 12, 2022 at 10:44:38AM +1200, Thomas Munro wrote:
> On Sat, Sep 10, 2022 at 5:44 PM Justin Pryzby <pry...@telsasoft.com> wrote:
> > < 2022-09-09 19:37:25.835 CDT telsasoft >ERROR: MultiXactId 133553154 has
> > not been created yet -- apparent wraparound
>
> I guess what happened here is that after one of your (apparently
> several?) OOM crashes, crash recovery didn't run all the way to the
> true end of the WAL due to the maintenance_io_concurrency=0 bug. In
> the case you reported, it couldn't complete an end-of-recovery
> checkpoint until you disabled recovery_prefetch, but that's only
> because of the somewhat unusual way that vismap pages work. In
> another case it might have been able to (bogusly) complete a
> checkpoint, leaving things in an inconsistent state.
I think you're saying is that this can be explained by the
io_concurrency bug in recovery_prefetch, if run under 15b3.
But yesterday I started from initdb and restored this cluster from backup, and
started up sqlsmith, and sent some kill -9, and now got more corruption.
Looks like it took ~10 induced crashes before this happened.
At the moment, I have no reason to believe this issue is related to
prefetch_recovery; I am wondering about changes to vacuum.
< 2022-09-11 20:19:03.071 CDT telsasoft >ERROR: MultiXactId 732646 has not
been created yet -- apparent wraparound
< 2022-09-11 20:24:00.530 CDT telsasoft >ERROR: MultiXactId 732646 has not
been created yet -- apparent wraparound
Program terminated with signal 6, Aborted.
#0 0x00007f413716b1f7 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install
glibc-2.17-196.el7_4.2.x86_64 libgcc-4.8.5-44.el7.x86_64
libxml2-2.9.1-6.el7_9.6.x86_64 lz4-1.8.3-1.el7.x86_64
xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) bt
#0 0x00007f413716b1f7 in raise () from /lib64/libc.so.6
#1 0x00007f413716c8e8 in abort () from /lib64/libc.so.6
#2 0x0000000000962c5c in ExceptionalCondition
(conditionName=conditionName@entry=0x9ce238 "P_ISLEAF(opaque) &&
!P_ISDELETED(opaque)", errorType=errorType@entry=0x9bad97 "FailedAssertion",
fileName=fileName@entry=0x9cdcd1 "nbtpage.c",
lineNumber=lineNumber@entry=1778) at assert.c:69
#3 0x0000000000507e34 in _bt_rightsib_halfdeadflag
(rel=rel@entry=0x7f4138a238a8, leafrightsib=leafrightsib@entry=53) at
nbtpage.c:1778
#4 0x0000000000507fba in _bt_mark_page_halfdead (rel=rel@entry=0x7f4138a238a8,
leafbuf=leafbuf@entry=13637, stack=stack@entry=0x144ca20) at nbtpage.c:2121
#5 0x000000000050af1d in _bt_pagedel (rel=rel@entry=0x7f4138a238a8,
leafbuf=leafbuf@entry=13637, vstate=vstate@entry=0x7ffef18de8b0) at
nbtpage.c:2004
#6 0x000000000050c996 in btvacuumpage (vstate=vstate@entry=0x7ffef18de8b0,
scanblkno=scanblkno@entry=36) at nbtree.c:1342
#7 0x000000000050caf8 in btvacuumscan (info=info@entry=0x7ffef18deac0,
stats=stats@entry=0x142fb70, callback=callback@entry=0x67e89b <vac_tid_reaped>,
callback_state=callback_state@entry=0x1461220, cycleid=<optimized out>)
at nbtree.c:997
#8 0x000000000050cc2f in btbulkdelete (info=0x7ffef18deac0, stats=0x142fb70,
callback=0x67e89b <vac_tid_reaped>, callback_state=0x1461220) at nbtree.c:801
#9 0x00000000004fc64b in index_bulk_delete (info=info@entry=0x7ffef18deac0,
istat=istat@entry=0x0, callback=callback@entry=0x67e89b <vac_tid_reaped>,
callback_state=callback_state@entry=0x1461220) at indexam.c:701
#10 0x000000000068108c in vac_bulkdel_one_index
(ivinfo=ivinfo@entry=0x7ffef18deac0, istat=istat@entry=0x0,
dead_items=0x1461220) at vacuum.c:2324
#11 0x00000000004f72ae in lazy_vacuum_one_index (indrel=<optimized out>,
istat=0x0, reltuples=<optimized out>, vacrel=vacrel@entry=0x142f100) at
vacuumlazy.c:2726
#12 0x00000000004f738b in lazy_vacuum_all_indexes
(vacrel=vacrel@entry=0x142f100) at vacuumlazy.c:2328
#13 0x00000000004f75df in lazy_vacuum (vacrel=vacrel@entry=0x142f100) at
vacuumlazy.c:2261
#14 0x00000000004f7f14 in lazy_scan_heap (vacrel=vacrel@entry=0x142f100) at
vacuumlazy.c:1264
#15 0x00000000004f895f in heap_vacuum_rel (rel=0x7f4138a67c00,
params=0x143cbec, bstrategy=0x143ea20) at vacuumlazy.c:534
#16 0x000000000067f62b in table_relation_vacuum (bstrategy=<optimized out>,
params=0x143cbec, rel=0x7f4138a67c00) at
../../../src/include/access/tableam.h:1680
#17 vacuum_rel (relid=1249, relation=<optimized out>,
params=params@entry=0x143cbec) at vacuum.c:2086
#18 0x000000000068065c in vacuum (relations=0x144a118,
params=params@entry=0x143cbec, bstrategy=<optimized out>,
bstrategy@entry=0x143ea20, isTopLevel=isTopLevel@entry=true) at vacuum.c:475
#19 0x0000000000796a0e in autovacuum_do_vac_analyze (tab=tab@entry=0x143cbe8,
bstrategy=bstrategy@entry=0x143ea20) at autovacuum.c:3149
#20 0x00000000007987bf in do_autovacuum () at autovacuum.c:2472
#21 0x0000000000798e72 in AutoVacWorkerMain (argc=argc@entry=0,
argv=argv@entry=0x0) at autovacuum.c:1715
#22 0x0000000000798eed in StartAutoVacWorker () at autovacuum.c:1493
#23 0x000000000079fe49 in StartAutovacuumWorker () at postmaster.c:5534
#24 0x00000000007a0c44 in sigusr1_handler (postgres_signal_arg=<optimized out>)
at postmaster.c:5239
#25 <signal handler called>
#26 0x00007f4137225783 in __select_nocancel () from /lib64/libc.so.6
#27 0x00000000007a0fc5 in ServerLoop () at postmaster.c:1770
#28 0x00000000007a2361 in PostmasterMain (argc=argc@entry=3,
argv=argv@entry=0x136e9d0) at postmaster.c:1478
#29 0x00000000006ed9c4 in main (argc=3, argv=0x136e9d0) at main.c:202
#2 0x0000000000962c5c in ExceptionalCondition
(conditionName=conditionName@entry=0xaa6a32 "false",
errorType=errorType@entry=0x9bad97 "FailedAssertion",
fileName=fileName@entry=0x9c6207 "heapam.c",
lineNumber=lineNumber@entry=7803) at assert.c:69
#3 0x00000000004d9db9 in index_delete_sort_cmp (deltid2=0x7ffef18dcc90,
deltid1=<optimized out>) at heapam.c:7803
#4 index_delete_sort (delstate=delstate@entry=0x7ffef18ddf10) at heapam.c:7844
#5 0x00000000004e9323 in heap_index_delete_tuples (rel=0x7f4138a672b8,
delstate=0x7ffef18ddf10) at heapam.c:7502
#6 0x000000000050a512 in table_index_delete_tuples (delstate=0x7ffef18ddf10,
rel=0x0) at ../../../../src/include/access/tableam.h:1329
#7 _bt_delitems_delete_check (rel=rel@entry=0x7f41389dbea0,
buf=buf@entry=9183, heapRel=heapRel@entry=0x7f4138a672b8,
delstate=delstate@entry=0x7ffef18ddf10) at nbtpage.c:1540
#8 0x00000000004fff30 in _bt_simpledel_pass (rel=rel@entry=0x7f41389dbea0,
buffer=buffer@entry=9183, heapRel=heapRel@entry=0x7f4138a672b8,
deletable=deletable@entry=0x7ffef18ddfb0, ndeletable=4, newitem=<optimized
out>,
minoff=2, maxoff=215) at nbtinsert.c:2899
#9 0x0000000000500171 in _bt_delete_or_dedup_one_page
(rel=rel@entry=0x7f41389dbea0, heapRel=heapRel@entry=0x7f4138a672b8,
insertstate=insertstate@entry=0x7ffef18de3c0,
simpleonly=simpleonly@entry=false,
checkingunique=checkingunique@entry=true, uniquedup=uniquedup@entry=false,
indexUnchanged=indexUnchanged@entry=false) at nbtinsert.c:2710
#10 0x00000000005051ad in _bt_findinsertloc (rel=rel@entry=0x7f41389dbea0,
insertstate=insertstate@entry=0x7ffef18de3c0,
checkingunique=checkingunique@entry=true,
indexUnchanged=indexUnchanged@entry=false,
stack=stack@entry=0x157dbc8, heapRel=heapRel@entry=0x7f4138a672b8) at
nbtinsert.c:902
#11 0x00000000005055ad in _bt_doinsert (rel=rel@entry=0x7f41389dbea0,
itup=itup@entry=0x157dcc8, checkUnique=checkUnique@entry=UNIQUE_CHECK_YES,
indexUnchanged=indexUnchanged@entry=false, heapRel=heapRel@entry=0x7f4138a672b8)
at nbtinsert.c:256
#12 0x000000000050b16c in btinsert (rel=0x7f41389dbea0, values=<optimized out>,
isnull=<optimized out>, ht_ctid=0x157d1bc, heapRel=0x7f4138a672b8,
checkUnique=UNIQUE_CHECK_YES, indexUnchanged=false, indexInfo=0x1803df0)
at nbtree.c:200
#13 0x00000000004fb95d in index_insert
(indexRelation=indexRelation@entry=0x7f41389dbea0,
values=values@entry=0x7ffef18de520, isnull=isnull@entry=0x7ffef18de500,
heap_t_ctid=heap_t_ctid@entry=0x157d1bc,
heapRelation=heapRelation@entry=0x7f4138a672b8,
checkUnique=UNIQUE_CHECK_YES, indexUnchanged=indexUnchanged@entry=false,
indexInfo=indexInfo@entry=0x1803df0) at indexam.c:193
#14 0x0000000000581ae6 in CatalogIndexInsert
(indstate=indstate@entry=0x157c2f8, heapTuple=heapTuple@entry=0x157d1b8) at
indexing.c:158
#15 0x0000000000581b9f in CatalogTupleInsert
(heapRel=heapRel@entry=0x7f4138a672b8, tup=tup@entry=0x157d1b8) at
indexing.c:231
#16 0x000000000057996f in InsertPgClassTuple (pg_class_desc=0x7f4138a672b8,
new_rel_desc=new_rel_desc@entry=0x7f41389d9e30, new_rel_oid=<optimized out>,
relacl=relacl@entry=0, reloptions=reloptions@entry=0) at heap.c:939
#17 0x0000000000579a07 in AddNewRelationTuple
(pg_class_desc=pg_class_desc@entry=0x7f4138a672b8,
new_rel_desc=new_rel_desc@entry=0x7f41389d9e30,
new_rel_oid=new_rel_oid@entry=500038, new_type_oid=new_type_oid@entry=0,
reloftype=reloftype@entry=0, relowner=relowner@entry=16556,
relkind=relkind@entry=116 't', relfrozenxid=17414307, relminmxid=730642,
relacl=relacl@entry=0, reloptions=reloptions@entry=0) at heap.c:998
#18 0x000000000057a204 in heap_create_with_catalog
(relname=relname@entry=0x7ffef18dea90 "pg_toast_500035",
relnamespace=relnamespace@entry=20138, reltablespace=<optimized out>,
relid=500038, relid@entry=0,
reltypeid=reltypeid@entry=0, reloftypeid=reloftypeid@entry=0,
ownerid=16556, accessmtd=2, tupdesc=tupdesc@entry=0x1800420,
cooked_constraints=cooked_constraints@entry=0x0, relkind=relkind@entry=116 't',
relpersistence=relpersistence@entry=116 't',
shared_relation=shared_relation@entry=false,
mapped_relation=mapped_relation@entry=false,
oncommit=oncommit@entry=ONCOMMIT_NOOP, reloptions=reloptions@entry=0,
use_user_acl=use_user_acl@entry=false,
allow_system_table_mods=allow_system_table_mods@entry=true,
is_internal=is_internal@entry=true, relrewrite=relrewrite@entry=0,
typaddress=typaddress@entry=0x0) at heap.c:1386
#19 0x00000000005a41e2 in create_toast_table (rel=rel@entry=0x7f41389ddfb8,
toastOid=toastOid@entry=0, toastIndexOid=toastIndexOid@entry=0,
reloptions=reloptions@entry=0, lockmode=lockmode@entry=8,
check=check@entry=false,
OIDOldToast=OIDOldToast@entry=0) at toasting.c:249
#20 0x00000000005a4571 in CheckAndCreateToastTable (relOid=relOid@entry=500035,
reloptions=reloptions@entry=0, lockmode=lockmode@entry=8,
check=check@entry=false, OIDOldToast=OIDOldToast@entry=0) at toasting.c:88
#21 0x00000000005a45d3 in NewRelationCreateToastTable
(relOid=relOid@entry=500035, reloptions=reloptions@entry=0) at toasting.c:75
#22 0x0000000000609e47 in create_ctas_internal
(attrList=attrList@entry=0x17ff798, into=into@entry=0x1374c80) at createas.c:135
#23 0x000000000060a0cf in intorel_startup (self=0x1547678, operation=<optimized
out>, typeinfo=0x17fc530) at createas.c:528
#24 0x0000000000694b1e in standard_ExecutorRun
(queryDesc=queryDesc@entry=0x1569188,
direction=direction@entry=ForwardScanDirection, count=count@entry=0,
execute_once=execute_once@entry=true) at execMain.c:352
#25 0x00007f41307d2a2e in pgss_ExecutorRun (queryDesc=0x1569188,
direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at
pg_stat_statements.c:1010
#26 0x00007f41303af648 in explain_ExecutorRun (queryDesc=0x1569188,
direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at
auto_explain.c:320
#27 0x0000000000694c13 in ExecutorRun (queryDesc=queryDesc@entry=0x1569188,
direction=direction@entry=ForwardScanDirection, count=count@entry=0,
execute_once=execute_once@entry=true) at execMain.c:305
#28 0x000000000060a894 in ExecCreateTableAs (pstate=pstate@entry=0x14bd950,
stmt=stmt@entry=0x1545140, params=params@entry=0x0,
queryEnv=queryEnv@entry=0x0, qc=qc@entry=0x7ffef18df720) at createas.c:336
#29 0x00000000008378dc in ProcessUtilitySlow (pstate=pstate@entry=0x14bd950,
pstmt=pstmt@entry=0x15ce250,
queryString=queryString@entry=0x1373df0 "\n-- do paging
substitutions\nCREATE TEMPORARY TABLE SU AS\n\tSELECT ...
