Thread: BUG #17197: Assert failed on inserting index tuples after VACUUM

The following bug has been logged on the website:

Bug reference:      17197
Logged by:          Alexander Lakhin
Email address:      exclusion@gmail.com
PostgreSQL version: 14beta3
Operating system:   Ubuntu 20.04
Description:

The following made-up query:
echo "create table parent1(f1 int, constraint f1chk check (f1>0));" >q.sql
{ for i in `seq 18`;    do echo "create table t$i(f2 int)
inherits(parent1);"; done } >>q.sql
{ for i in `seq 1200`;  do echo "alter table parent1 alter column f1 type
bigint;"; done } >>q.sql
echo "vacuum;" >>q.sql
{ for i in `seq 20 23`; do echo "create table t$i(f1 int primary key);";
done } >>q.sql;
# (Without a doubt, such state of an index could be achieved with a less
extravagant approach.)

Leads to an assertion failure with the following stack trace:
Core was generated by `postgres: law regression [local] CREATE TABLE
                        '.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f16181d9859 in __GI_abort () at abort.c:79
#2  0x000055672da7aa44 in ExceptionalCondition
(conditionName=conditionName@entry=0x55672dbb614d "false", 
    errorType=errorType@entry=0x55672dada00b "FailedAssertion",
fileName=0x7ffe13a0a770 "%\252\247-gU", 
    fileName@entry=0x55672dae546d "heapam.c",
lineNumber=lineNumber@entry=7489) at assert.c:69
#3  0x000055672d5cbc8a in heap_index_delete_tuples (rel=0x7f160cff1258,
delstate=0x7ffe13a0bcc0) at heapam.c:7489
#4  0x000055672d5f1d0f in table_index_delete_tuples
(delstate=0x7ffe13a0bcc0, rel=0xcc)
    at ../../../../src/include/access/tableam.h:1327
#5  _bt_delitems_delete_check (rel=rel@entry=0x7f160d062fd8,
buf=buf@entry=259, heapRel=heapRel@entry=0x7f160cff1258, 
    delstate=delstate@entry=0x7ffe13a0bcc0) at nbtpage.c:1541
#6  0x000055672d5e5c03 in _bt_simpledel_pass (rel=rel@entry=0x7f160d062fd8,
buffer=buffer@entry=259, 
    heapRel=heapRel@entry=0x7f160cff1258,
deletable=deletable@entry=0x7ffe13a0bd60, ndeletable=76, 
    newitem=<optimized out>, minoff=1, maxoff=204) at nbtinsert.c:2880
#7  0x000055672d5e5f2d in _bt_delete_or_dedup_one_page
(rel=rel@entry=0x7f160d062fd8, 
    heapRel=heapRel@entry=0x7f160cff1258,
insertstate=insertstate@entry=0x7ffe13a0c170, 
    simpleonly=simpleonly@entry=false,
checkingunique=checkingunique@entry=true, uniquedup=uniquedup@entry=false,

    indexUnchanged=false) at nbtinsert.c:2693
#8  0x000055672d5eb80b in _bt_findinsertloc (rel=rel@entry=0x7f160d062fd8,

    insertstate=insertstate@entry=0x7ffe13a0c170,
checkingunique=checkingunique@entry=true, 
    indexUnchanged=indexUnchanged@entry=false, stack=stack@entry=0x0,
heapRel=heapRel@entry=0x7f160cff1258)
    at nbtinsert.c:904
#9  0x000055672d5ebbda in _bt_doinsert (rel=rel@entry=0x7f160d062fd8,
itup=itup@entry=0x55672e2a71b0, 
    checkUnique=checkUnique@entry=UNIQUE_CHECK_YES,
indexUnchanged=indexUnchanged@entry=false, 
    heapRel=heapRel@entry=0x7f160cff1258) at nbtinsert.c:255
#10 0x000055672d5f2b97 in btinsert (rel=0x7f160d062fd8, values=<optimized
out>, isnull=<optimized out>, 
    ht_ctid=0x55672e2a66c4, heapRel=0x7f160cff1258,
checkUnique=UNIQUE_CHECK_YES, indexUnchanged=false, 
    indexInfo=0x55672e2a6e68) at nbtree.c:199
#11 0x000055672d5e0c9d in index_insert
(indexRelation=indexRelation@entry=0x7f160d062fd8, 
    values=values@entry=0x7ffe13a0c2e0, isnull=isnull@entry=0x7ffe13a0c2c0,

    heap_t_ctid=heap_t_ctid@entry=0x55672e2a66c4,
heapRelation=heapRelation@entry=0x7f160cff1258, 
    checkUnique=UNIQUE_CHECK_YES, indexUnchanged=false,
indexInfo=0x55672e2a6e68) at indexam.c:193
#12 0x000055672d667aac in CatalogIndexInsert
(indstate=indstate@entry=0x55672e328360, 
    heapTuple=heapTuple@entry=0x55672e2a66c0) at indexing.c:158
#13 0x000055672d667b84 in CatalogTupleInsert
(heapRel=heapRel@entry=0x7f160cff1258, tup=0x55672e2a66c0)
    at indexing.c:231
#14 0x000055672d67a465 in CreateConstraintEntry
(constraintName=constraintName@entry=0x55672e2a4580 "t22_pkey", 
    constraintNamespace=constraintNamespace@entry=2200,
constraintType=constraintType@entry=112 'p', 
    isDeferrable=isDeferrable@entry=false,
isDeferred=isDeferred@entry=false, isValidated=isValidated@entry=true, 
    parentConstrId=0, relId=39328, constraintKey=0x55672e2a306c,
constraintNKeys=1, constraintNTotalKeys=1, domainId=0, 
    indexRelId=39331, foreignRelId=0, foreignKey=0x0, pfEqOp=0x0,
ppEqOp=0x0, ffEqOp=0x0, foreignNKeys=0, 
    foreignUpdateType=32 ' ', foreignDeleteType=32 ' ', foreignMatchType=32
' ', exclOp=0x0, conExpr=0x0, conBin=0x0, 
    conIsLocal=true, conInhCount=0, conNoInherit=true, is_internal=false) at
pg_constraint.c:226
#15 0x000055672d6637af in index_constraint_create
(heapRelation=heapRelation@entry=0x7f160cff4b38, 
    indexRelationId=indexRelationId@entry=39331,
parentConstraintId=parentConstraintId@entry=0, 
    indexInfo=indexInfo@entry=0x55672e2a3060,
constraintName=constraintName@entry=0x55672e2a4580 "t22_pkey", 
    constraintType=<optimized out>, constr_flags=0,
allow_system_table_mods=false, is_internal=false) at index.c:1941
#16 0x000055672d666b95 in index_create
(heapRelation=heapRelation@entry=0x7f160cff4b38, 
    indexRelationName=indexRelationName@entry=0x55672e2a4580 "t22_pkey",
indexRelationId=39331, 
    indexRelationId@entry=0, parentIndexRelid=parentIndexRelid@entry=0,
parentConstraintId=parentConstraintId@entry=0, 
    relFileNode=0, indexInfo=0x55672e2a3060, indexColNames=0x55672e2a4728,
accessMethodObjectId=403, tableSpaceId=0, 
    collationObjectId=0x55672e2a47d0, classObjectId=0x55672e2a47f0,
coloptions=0x55672e2a4810, reloptions=0, flags=3, 
    constr_flags=0, allow_system_table_mods=false, is_internal=false,
constraintId=0x7ffe13a0ca00) at index.c:1057
#17 0x000055672d716f13 in DefineIndex (relationId=relationId@entry=39328,
stmt=stmt@entry=0x55672e311af0, 
    indexRelationId=indexRelationId@entry=0,
parentIndexId=parentIndexId@entry=0, 
    parentConstraintId=parentConstraintId@entry=0,
is_alter_table=is_alter_table@entry=false, check_rights=true, 
    check_not_in_use=true, skip_build=false, quiet=false) at
indexcmds.c:1137
#18 0x000055672d940e6a in ProcessUtilitySlow
(pstate=pstate@entry=0x55672e2a34f8, pstmt=pstmt@entry=0x55672e2a0270, 
    queryString=queryString@entry=0x55672e1a74d0 "create table t22(f1 int
primary key);", 
    context=context@entry=PROCESS_UTILITY_SUBCOMMAND,
params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, 
    dest=0x55672dd6c740 <donothingDR>, qc=0x0) at utility.c:1534
#19 0x000055672d940388 in standard_ProcessUtility (pstmt=0x55672e2a0270, 
    queryString=0x55672e1a74d0 "create table t22(f1 int primary key);",
readOnlyTree=readOnlyTree@entry=false, 
    context=PROCESS_UTILITY_SUBCOMMAND, params=0x0, queryEnv=0x0,
dest=0x55672dd6c740 <donothingDR>, qc=0x0)
    at utility.c:1066
#20 0x000055672d940471 in ProcessUtility (pstmt=<optimized out>, 
    queryString=queryString@entry=0x55672e1a74d0 "create table t22(f1 int
primary key);", 
    readOnlyTree=readOnlyTree@entry=false,
context=context@entry=PROCESS_UTILITY_SUBCOMMAND, params=params@entry=0x0,

    queryEnv=queryEnv@entry=0x0, dest=0x55672dd6c740 <donothingDR>, qc=0x0)
at utility.c:527
#21 0x000055672d9407ae in ProcessUtilitySlow
(pstate=pstate@entry=0x55672e1c9560, pstmt=pstmt@entry=0x55672e1a8610, 
    queryString=queryString@entry=0x55672e1a74d0 "create table t22(f1 int
primary key);", 
    context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0,
queryEnv=queryEnv@entry=0x0, 
    dest=0x55672e1a86e0, qc=0x7ffe13a0d3a0) at utility.c:1244
#22 0x000055672d940388 in standard_ProcessUtility (pstmt=0x55672e1a8610, 
    queryString=0x55672e1a74d0 "create table t22(f1 int primary key);",
readOnlyTree=<optimized out>, 
    context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
dest=0x55672e1a86e0, qc=0x7ffe13a0d3a0)
    at utility.c:1066
#23 0x000055672d940471 in ProcessUtility (pstmt=pstmt@entry=0x55672e1a8610,
queryString=<optimized out>, 
    readOnlyTree=<optimized out>,
context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=<optimized out>, 
    queryEnv=<optimized out>, dest=0x55672e1a86e0, qc=0x7ffe13a0d3a0) at
utility.c:527
#24 0x000055672d93d847 in PortalRunUtility
(portal=portal@entry=0x55672e209110, pstmt=pstmt@entry=0x55672e1a8610, 
    isTopLevel=isTopLevel@entry=true,
setHoldSnapshot=setHoldSnapshot@entry=false, dest=dest@entry=0x55672e1a86e0,

    qc=qc@entry=0x7ffe13a0d3a0) at pquery.c:1147
#25 0x000055672d93db4c in PortalRunMulti
(portal=portal@entry=0x55672e209110, isTopLevel=isTopLevel@entry=true, 
    setHoldSnapshot=setHoldSnapshot@entry=false,
dest=dest@entry=0x55672e1a86e0, altdest=altdest@entry=0x55672e1a86e0, 
    qc=qc@entry=0x7ffe13a0d3a0) at pquery.c:1304
#26 0x000055672d93df80 in PortalRun (portal=portal@entry=0x55672e209110,
count=count@entry=9223372036854775807, 
    isTopLevel=isTopLevel@entry=true, run_once=run_once@entry=true,
dest=dest@entry=0x55672e1a86e0, 
    altdest=altdest@entry=0x55672e1a86e0, qc=0x7ffe13a0d3a0) at
pquery.c:786
#27 0x000055672d93a17f in exec_simple_query (
    query_string=query_string@entry=0x55672e1a74d0 "create table t22(f1 int
primary key);") at postgres.c:1214
#28 0x000055672d93c15f in PostgresMain (argc=argc@entry=1,
argv=argv@entry=0x7ffe13a0d590, dbname=<optimized out>, 
    username=<optimized out>) at postgres.c:4486
#29 0x000055672d896c54 in BackendRun (port=port@entry=0x55672e1ca920) at
postmaster.c:4506
#30 0x000055672d899e3d in BackendStartup (port=port@entry=0x55672e1ca920) at
postmaster.c:4228
#31 0x000055672d89a076 in ServerLoop () at postmaster.c:1745
#32 0x000055672d89b5bd in PostmasterMain (argc=3, argv=<optimized out>) at
postmaster.c:1417
#33 0x000055672d7dbf20 in main (argc=3, argv=0x55672e1a1540) at main.c:209

Reproduced on REL_14_STABLE and master.
The first bad commit is 3c3b8a4b.

On Mon, Sep 20, 2021 at 1:01 PM PG Bug reporting form
<noreply@postgresql.org> wrote:
> Reproduced on REL_14_STABLE and master.
> The first bad commit is 3c3b8a4b.

I committed both the patch that added the failing assertion (bugfix
commit 4228817449) and the commit that allowed VACUUM to truncate line
pointers (commit 3c3b8a4b, "the first bad commit"). So I am very much
involved with both sides of the assertion failure that you found.

I am tempted to say that I should simply remove the assertion that
fails. But I won't do that before understanding what's going on here.

This is the assertion in question:

        offnum = ItemPointerGetOffsetNumber(htid);
        priorXmax = InvalidTransactionId;   /* cannot check first XMIN */
        for (;;)
        {
            ItemId      lp;
            HeapTupleHeader htup;

            /* Some sanity checks */
            if (offnum < FirstOffsetNumber || offnum > maxoff)
            {
                Assert(false);
                break;
            }

Similar code from heap_prune_chain() does not have the assertion. In
fact it's almost identical. This "can't happen" assertion was my own
recent addition, that could have easily been left out of commit
4228817449.

If this is a TID that came from the index then I cannot see what
business VACUUM has with setting it LP_UNUSED (and then truncating it
away entirely) -- clearly VACUUM should have deleted it from the index
first. Is there any easy way for you to check where this offnum came
from?

-- 
Peter Geoghegan

On Mon, Sep 20, 2021 at 1:35 PM Peter Geoghegan <pg@bowt.ie> wrote:
> If this is a TID that came from the index then I cannot see what
> business VACUUM has with setting it LP_UNUSED (and then truncating it
> away entirely) -- clearly VACUUM should have deleted it from the index
> first. Is there any easy way for you to check where this offnum came
> from?

Oh, wait. The problem now seems obvious: the assertion is wrong, and
should just be removed. The assertion was arguably a bit too zealous
when 4228817449 went in, and clearly became totally wrong a few months
later, following commit 3c3b8a4b.

Before commit 3c3b8a4b our failing offset number would have at least
found an LP_UNUSED item -- so no assertion failure. After that commit
the offset's line pointer might actually be positioned "past the end
of the line pointer array". But that is a valid state for a heap
page/HOT chain to have -- so the assertion has it wrong.

It is actually the job of code that traverses HOT chains to deal with
these sorts of inconsistencies, at least following commit 3c3b8a4b --
the responsibility does not belong to the pruning process itself.
That's why commit 3c3b8a4b went to the trouble of tightening things up
elsewhere (e.g., in heap_get_root_tuples()).

I'll push a fix soon. Thanks for the report!

-- 
Peter Geoghegan

Hello Peter,

21.09.2021 00:03, Peter Geoghegan wrote:
> On Mon, Sep 20, 2021 at 1:35 PM Peter Geoghegan <pg@bowt.ie> wrote:
> Before commit 3c3b8a4b our failing offset number would have at least
> found an LP_UNUSED item -- so no assertion failure. After that commit
> the offset's line pointer might actually be positioned "past the end
> of the line pointer array". But that is a valid state for a heap
> page/HOT chain to have -- so the assertion has it wrong.
>
> I'll push a fix soon. Thanks for the report!
Thanks for the fix!
But if that is a valid (or sane) state, then shouldn't the comment "Some
sanity checks" be removed (or updated) too?

Best regards,
Alexander

Hi Alexander,

On Mon, Sep 20, 2021 at 10:00 PM Alexander Lakhin <exclusion@gmail.com> wrote:
> Thanks for the fix!
> But if that is a valid (or sane) state, then shouldn't the comment "Some
> sanity checks" be removed (or updated) too?

I think that that's a good idea. I pushed a commit that updates these
comments just now.

Thanks again
--
Peter Geoghegan