Обсуждение: BUG #18396: Assert in gistFindCorrectParent() fails on inserting large tuples into gist index

Поиск
Список
Период
Сортировка

BUG #18396: Assert in gistFindCorrectParent() fails on inserting large tuples into gist index

От
PG Bug reporting form
Дата:
The following bug has been logged on the website:

Bug reference:      18396
Logged by:          Alexander Lakhin
Email address:      exclusion@gmail.com
PostgreSQL version: 16.2
Operating system:   Ubuntu 22.04
Description:

The following script:
psql -c "CREATE EXTENSION btree_gist;"
numclients=50
for ((i=1;i<=100;i++)); do
  echo "iteration $i"
  for ((c=1;c<=$numclients;c++)); do
    echo "
CREATE TEMP TABLE t (a text);
CREATE INDEX idx ON t USING GIST (a);

INSERT INTO t SELECT '' FROM generate_series(1, 500) g;
INSERT INTO t SELECT
 (SELECT string_agg('text' || g, ' ') FROM generate_series(1, 600) g)
 FROM generate_series(1, 30);
" | psql >psql-$c.log &
  done
wait
grep 'TRAP:' server.log  && { res=0; break; }
done

triggers an assertion failure:
...
iteration 4
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
connection to server was lost
TRAP: failed Assert("parent->lsn != PageGetLSN(parent->page) || is_build"),
File: "gist.c", Line: 1050, PID: 789065

with the stack trace:
#0  __pthread_kill_implementation (no_tid=0, signo=6,
threadid=140380599453504) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=140380599453504) at
./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=140380599453504, signo=signo@entry=6) at
./nptl/pthread_kill.c:89
#3  0x00007face7209476 in __GI_raise (sig=sig@entry=6) at
../sysdeps/posix/raise.c:26
#4  0x00007face71ef7f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x0000558b58981037 in ExceptionalCondition
(conditionName=conditionName@entry=0x558b589e6a80 "parent->lsn !=
PageGetLSN(parent->page) || is_build",
fileName=fileName@entry=0x558b58b44840 "gist.c",
lineNumber=lineNumber@entry=1050)
    at assert.c:66
#6  0x0000558b58452dc3 in gistFindCorrectParent (r=0x7facdb4a6760,
child=child@entry=0x558b5978ac68, is_build=<optimized out>) at gist.c:1050
#7  0x0000558b58455407 in gistfinishsplit (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b5978ac68, giststate=giststate@entry=0x558b59712ad8,
splitinfo=<optimized out>, unlockbuf=unlockbuf@entry=true) at gist.c:1394
#8  0x0000558b58455122 in gistinserttuples
(state=state@entry=0x7ffd28324ee0, stack=0x558b5978ac68,
giststate=giststate@entry=0x558b59712ad8,
tuples=tuples@entry=0x7ffd28324c80, ntup=ntup@entry=2, oldoffnum=<optimized
out>, 
    leftchild=-37, rightchild=-40, unlockbuf=true, unlockleftchild=false) at
gist.c:1324
#9  0x0000558b58455437 in gistfinishsplit (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b59720148, giststate=giststate@entry=0x558b59712ad8,
splitinfo=<optimized out>, unlockbuf=unlockbuf@entry=false) at gist.c:1395
#10 0x0000558b58455122 in gistinserttuples
(state=state@entry=0x7ffd28324ee0, stack=0x558b59720148,
giststate=giststate@entry=0x558b59712ad8,
tuples=tuples@entry=0x558b59760c60, ntup=ntup@entry=1,
oldoffnum=oldoffnum@entry=0, 
    leftchild=-33, rightchild=-34, unlockbuf=false, unlockleftchild=false)
at gist.c:1324
#11 0x0000558b584552ee in gistfinishsplit (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b59738178, giststate=giststate@entry=0x558b59712ad8,
splitinfo=0x558b59760be8, unlockbuf=unlockbuf@entry=false) at gist.c:1370
#12 0x0000558b58455122 in gistinserttuples
(state=state@entry=0x7ffd28324ee0, stack=stack@entry=0x558b59738178,
giststate=giststate@entry=0x558b59712ad8,
tuples=tuples@entry=0x7ffd28324e78, ntup=ntup@entry=1, 
    oldoffnum=oldoffnum@entry=0, leftchild=0, rightchild=0, unlockbuf=false,
unlockleftchild=false) at gist.c:1324
#13 0x0000558b5845584e in gistinserttuple (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b59738178, giststate=giststate@entry=0x558b59712ad8,
tuple=<optimized out>, tuple@entry=0x558b5971b228,
oldoffnum=oldoffnum@entry=0)
    at gist.c:1250
#14 0x0000558b58455df0 in gistdoinsert (r=r@entry=0x7facdb4a6760,
itup=0x558b5971b228, freespace=freespace@entry=0,
giststate=giststate@entry=0x558b59712ad8,
heapRel=heapRel@entry=0x7facdb4a0e48, is_build=is_build@entry=false)
    at gist.c:886
#15 0x0000558b584568df in gistinsert (r=0x7facdb4a6760,
values=0x7ffd283250a0, isnull=0x7ffd28325080, ht_ctid=0x558b596f5428,
heapRel=0x7facdb4a0e48, checkUnique=<optimized out>, indexUnchanged=false,
indexInfo=0x558b596f6938)
    at gist.c:184
#16 0x0000558b5849b579 in index_insert
(indexRelation=indexRelation@entry=0x7facdb4a6760,
values=values@entry=0x7ffd283250a0, isnull=isnull@entry=0x7ffd28325080,
heap_t_ctid=heap_t_ctid@entry=0x558b596f5428, 
    heapRelation=heapRelation@entry=0x7facdb4a0e48,
checkUnique=checkUnique@entry=UNIQUE_CHECK_NO, indexUnchanged=false,
indexInfo=0x558b596f6938) at indexam.c:235
#17 0x0000558b5864e668 in ExecInsertIndexTuples
(resultRelInfo=resultRelInfo@entry=0x558b596de518,
slot=slot@entry=0x558b596f53f8, estate=estate@entry=0x558b596ba2f8,
update=update@entry=false, noDupErr=noDupErr@entry=false, 
    specConflict=specConflict@entry=0x0, arbiterIndexes=0x0,
onlySummarizing=false) at execIndexing.c:432
#18 0x0000558b5868422f in ExecInsert (context=context@entry=0x7ffd28325300,
resultRelInfo=resultRelInfo@entry=0x558b596de518, slot=0x558b596f53f8,
canSetTag=true, inserted_tuple=inserted_tuple@entry=0x0, 
    insert_destrel=insert_destrel@entry=0x0) at nodeModifyTable.c:1139
...

Reproduced on REL_12_STABLE .. master, starting from the commit 28d3c2ddc,
which introduced this assert.

(With s/600/700/ I'm also seeing
ERROR:  failed to add item to index page in "idx"
ERROR:  no empty local buffer available)




PG Bug reporting form <noreply@postgresql.org> 于2024年3月17日周日 23:39写道:
The following bug has been logged on the website:

Bug reference:      18396
Logged by:          Alexander Lakhin
Email address:      exclusion@gmail.com
PostgreSQL version: 16.2
Operating system:   Ubuntu 22.04
Description:       

The following script:
psql -c "CREATE EXTENSION btree_gist;"
numclients=50
for ((i=1;i<=100;i++)); do
  echo "iteration $i"
  for ((c=1;c<=$numclients;c++)); do
    echo "
CREATE TEMP TABLE t (a text);
CREATE INDEX idx ON t USING GIST (a);

INSERT INTO t SELECT '' FROM generate_series(1, 500) g;
INSERT INTO t SELECT
 (SELECT string_agg('text' || g, ' ') FROM generate_series(1, 600) g)
 FROM generate_series(1, 30);
" | psql >psql-$c.log &
  done
wait
grep 'TRAP:' server.log  && { res=0; break; }
done

triggers an assertion failure:
...
iteration 4
server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
connection to server was lost
TRAP: failed Assert("parent->lsn != PageGetLSN(parent->page) || is_build"),
File: "gist.c", Line: 1050, PID: 789065

with the stack trace:
#0  __pthread_kill_implementation (no_tid=0, signo=6,
threadid=140380599453504) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=140380599453504) at
./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=140380599453504, signo=signo@entry=6) at
./nptl/pthread_kill.c:89
#3  0x00007face7209476 in __GI_raise (sig=sig@entry=6) at
../sysdeps/posix/raise.c:26
#4  0x00007face71ef7f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x0000558b58981037 in ExceptionalCondition
(conditionName=conditionName@entry=0x558b589e6a80 "parent->lsn !=
PageGetLSN(parent->page) || is_build",
fileName=fileName@entry=0x558b58b44840 "gist.c",
lineNumber=lineNumber@entry=1050)
    at assert.c:66
#6  0x0000558b58452dc3 in gistFindCorrectParent (r=0x7facdb4a6760,
child=child@entry=0x558b5978ac68, is_build=<optimized out>) at gist.c:1050
#7  0x0000558b58455407 in gistfinishsplit (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b5978ac68, giststate=giststate@entry=0x558b59712ad8,
splitinfo=<optimized out>, unlockbuf=unlockbuf@entry=true) at gist.c:1394
#8  0x0000558b58455122 in gistinserttuples
(state=state@entry=0x7ffd28324ee0, stack=0x558b5978ac68,
giststate=giststate@entry=0x558b59712ad8,
tuples=tuples@entry=0x7ffd28324c80, ntup=ntup@entry=2, oldoffnum=<optimized
out>,
    leftchild=-37, rightchild=-40, unlockbuf=true, unlockleftchild=false) at
gist.c:1324
#9  0x0000558b58455437 in gistfinishsplit (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b59720148, giststate=giststate@entry=0x558b59712ad8,
splitinfo=<optimized out>, unlockbuf=unlockbuf@entry=false) at gist.c:1395
#10 0x0000558b58455122 in gistinserttuples
(state=state@entry=0x7ffd28324ee0, stack=0x558b59720148,
giststate=giststate@entry=0x558b59712ad8,
tuples=tuples@entry=0x558b59760c60, ntup=ntup@entry=1,
oldoffnum=oldoffnum@entry=0,
    leftchild=-33, rightchild=-34, unlockbuf=false, unlockleftchild=false)
at gist.c:1324
#11 0x0000558b584552ee in gistfinishsplit (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b59738178, giststate=giststate@entry=0x558b59712ad8,
splitinfo=0x558b59760be8, unlockbuf=unlockbuf@entry=false) at gist.c:1370
#12 0x0000558b58455122 in gistinserttuples
(state=state@entry=0x7ffd28324ee0, stack=stack@entry=0x558b59738178,
giststate=giststate@entry=0x558b59712ad8,
tuples=tuples@entry=0x7ffd28324e78, ntup=ntup@entry=1,
    oldoffnum=oldoffnum@entry=0, leftchild=0, rightchild=0, unlockbuf=false,
unlockleftchild=false) at gist.c:1324
#13 0x0000558b5845584e in gistinserttuple (state=state@entry=0x7ffd28324ee0,
stack=stack@entry=0x558b59738178, giststate=giststate@entry=0x558b59712ad8,
tuple=<optimized out>, tuple@entry=0x558b5971b228,
oldoffnum=oldoffnum@entry=0)
    at gist.c:1250
#14 0x0000558b58455df0 in gistdoinsert (r=r@entry=0x7facdb4a6760,
itup=0x558b5971b228, freespace=freespace@entry=0,
giststate=giststate@entry=0x558b59712ad8,
heapRel=heapRel@entry=0x7facdb4a0e48, is_build=is_build@entry=false)
    at gist.c:886
#15 0x0000558b584568df in gistinsert (r=0x7facdb4a6760,
values=0x7ffd283250a0, isnull=0x7ffd28325080, ht_ctid=0x558b596f5428,
heapRel=0x7facdb4a0e48, checkUnique=<optimized out>, indexUnchanged=false,
indexInfo=0x558b596f6938)
    at gist.c:184
#16 0x0000558b5849b579 in index_insert
(indexRelation=indexRelation@entry=0x7facdb4a6760,
values=values@entry=0x7ffd283250a0, isnull=isnull@entry=0x7ffd28325080,
heap_t_ctid=heap_t_ctid@entry=0x558b596f5428,
    heapRelation=heapRelation@entry=0x7facdb4a0e48,
checkUnique=checkUnique@entry=UNIQUE_CHECK_NO, indexUnchanged=false,
indexInfo=0x558b596f6938) at indexam.c:235
#17 0x0000558b5864e668 in ExecInsertIndexTuples
(resultRelInfo=resultRelInfo@entry=0x558b596de518,
slot=slot@entry=0x558b596f53f8, estate=estate@entry=0x558b596ba2f8,
update=update@entry=false, noDupErr=noDupErr@entry=false,
    specConflict=specConflict@entry=0x0, arbiterIndexes=0x0,
onlySummarizing=false) at execIndexing.c:432
#18 0x0000558b5868422f in ExecInsert (context=context@entry=0x7ffd28325300,
resultRelInfo=resultRelInfo@entry=0x558b596de518, slot=0x558b596f53f8,
canSetTag=true, inserted_tuple=inserted_tuple@entry=0x0,
    insert_destrel=insert_destrel@entry=0x0) at nodeModifyTable.c:1139
...

Reproduced on REL_12_STABLE .. master, starting from the commit 28d3c2ddc,
which introduced this assert.

Thanks for your report. I can reproduce this issue.
I try to delete the Assert, no coredump anymore.
I need some time to learn GiST to find the root cause. 

--
Tender Wang
OpenPie:  https://en.openpie.com/
On 19/03/2024 14:07, Tender Wang wrote:
> Thanks for your report. I can reproduce this issue.
> I try to delete the Assert, no coredump anymore.
> I need some time to learn GiST to find the root cause.
At first glance, I think the assertion is too strict. In 
gistFindCorrectParent(), if we walk right, we update the parent's block 
number and reset its memorized downlinkoffnum to InvalidOffsetNumber. If 
we later call gistFindCorrectParent() again with the same stack, because 
the parent also needs to be split, we hit that assertion. But it's OK in 
that case, we don't know the downlink because we had moved right. 
Attached patch relaxes that.

But now I'm having some second thoughts. gistFindCorrectParent() looks 
like this:

>     /*
>      * Scan the page to re-find the downlink. If the page was split, it might
>      * have moved to a different page, so follow the right links until we find
>      * it.
>      */
>     while (true)
>     {
>         OffsetNumber i;
> 
>         maxoff = PageGetMaxOffsetNumber(parent->page);
>         for (i = FirstOffsetNumber; i <= maxoff; i = OffsetNumberNext(i))
>         {
>             iid = PageGetItemId(parent->page, i);
>             idxtuple = (IndexTuple) PageGetItem(parent->page, iid);
>             if (ItemPointerGetBlockNumber(&(idxtuple->t_tid)) == child->blkno)
>             {
>                 /* yes!!, found */
>                 child->downlinkoffnum = i;
>                 return;
>             }
>         }
> 
>         parent->blkno = GistPageGetOpaque(parent->page)->rightlink;
>         parent->downlinkoffnum = InvalidOffsetNumber;
>         UnlockReleaseBuffer(parent->buffer);
>         if (parent->blkno == InvalidBlockNumber)
>         {
>             /*
>              * End of chain and still didn't find parent. It's a very-very
>              * rare situation when the root was split.
>              */
>             break;
>         }
>         parent->buffer = ReadBuffer(r, parent->blkno);
>         LockBuffer(parent->buffer, GIST_EXCLUSIVE);
>         gistcheckpage(r, parent->buffer);
>         parent->page = (Page) BufferGetPage(parent->buffer);
>     }

When we step right and update parent->blkno, shouldn't we also update 
parent->lsn? Otherwise, we might fail to detect a concurrent page split 
with the LSN-NSN interlock checks. Or maybe it's correct, and we should 
indeed not update the memorized LSN. Or maybe it doesn't matter because 
we retry from the parent anyway, thanks to the 'retry_from_parent' flag? 
I'm not sure..

If you're interested to work on this, Tender, maybe you can figure that out?

-- 
Heikki Linnakangas
Neon (https://neon.tech)

Вложения
Hello Heikki and Tender Wang,

19.03.2024 17:26, Heikki Linnakangas wrote:
> On 19/03/2024 14:07, Tender Wang wrote:
>> Thanks for your report. I can reproduce this issue.
>> I try to delete the Assert, no coredump anymore.
>> I need some time to learn GiST to find the root cause.
>
> If you're interested to work on this, Tender, maybe you can figure that out?
>

Thank you for looking at this!

I'm also bothered by errors "no empty local buffer available" produced
(on master, but not on REL_12_STABLE) when inserting larger tuples:
INSERT INTO t SELECT '' FROM generate_series(1, 500) g;
INSERT INTO t SELECT
  (SELECT string_agg('text' || g, ' ') FROM generate_series(1, 700) g)
  FROM generate_series(1, 30);

Are those errors expected?

Best regards,
Alexander





Alexander Lakhin <exclusion@gmail.com> 于2024年3月20日周三 13:00写道:
Hello Heikki and Tender Wang,

19.03.2024 17:26, Heikki Linnakangas wrote:
> On 19/03/2024 14:07, Tender Wang wrote:
>> Thanks for your report. I can reproduce this issue.
>> I try to delete the Assert, no coredump anymore.
>> I need some time to learn GiST to find the root cause.
>
> If you're interested to work on this, Tender, maybe you can figure that out?
 
 I will take some time to figure that out.
 
>

Thank you for looking at this!

I'm also bothered by errors "no empty local buffer available" produced
(on master, but not on REL_12_STABLE) when inserting larger tuples:
INSERT INTO t SELECT '' FROM generate_series(1, 500) g;
INSERT INTO t SELECT
  (SELECT string_agg('text' || g, ' ') FROM generate_series(1, 700) g)
  FROM generate_series(1, 30);

Are those errors expected?
 
I think it is expected.  More local buffers need here. I set temp_buffers to 2GB.
this error didn't report. But stack depth limit exceeded. It is a hint that to process
this case need more resource.

--
Tender Wang
OpenPie:  https://en.openpie.com/


Heikki Linnakangas <hlinnaka@iki.fi> 于2024年3月19日周二 22:26写道:
On 19/03/2024 14:07, Tender Wang wrote:
> Thanks for your report. I can reproduce this issue.
> I try to delete the Assert, no coredump anymore.
> I need some time to learn GiST to find the root cause.
At first glance, I think the assertion is too strict. In
gistFindCorrectParent(), if we walk right, we update the parent's block
number and reset its memorized downlinkoffnum to InvalidOffsetNumber. If
we later call gistFindCorrectParent() again with the same stack, because
the parent also needs to be split, we hit that assertion. But it's OK in
that case, we don't know the downlink because we had moved right.
Attached patch relaxes that.

 I tested the code with attached patch many times. No failure anymore. 
+1 
But now I'm having some second thoughts. gistFindCorrectParent() looks
like this:

>       /*
>        * Scan the page to re-find the downlink. If the page was split, it might
>        * have moved to a different page, so follow the right links until we find
>        * it.
>        */
>       while (true)
>       {
>               OffsetNumber i;
>
>               maxoff = PageGetMaxOffsetNumber(parent->page);
>               for (i = FirstOffsetNumber; i <= maxoff; i = OffsetNumberNext(i))
>               {
>                       iid = PageGetItemId(parent->page, i);
>                       idxtuple = (IndexTuple) PageGetItem(parent->page, iid);
>                       if (ItemPointerGetBlockNumber(&(idxtuple->t_tid)) == child->blkno)
>                       {
>                               /* yes!!, found */
>                               child->downlinkoffnum = i;
>                               return;
>                       }
>               }
>
>               parent->blkno = GistPageGetOpaque(parent->page)->rightlink;
>               parent->downlinkoffnum = InvalidOffsetNumber;
>               UnlockReleaseBuffer(parent->buffer);
>               if (parent->blkno == InvalidBlockNumber)
>               {
>                       /*
>                        * End of chain and still didn't find parent. It's a very-very
>                        * rare situation when the root was split.
>                        */
>                       break;
>               }
>               parent->buffer = ReadBuffer(r, parent->blkno);
>               LockBuffer(parent->buffer, GIST_EXCLUSIVE);
>               gistcheckpage(r, parent->buffer);
>               parent->page = (Page) BufferGetPage(parent->buffer);
>       }

When we step right and update parent->blkno, shouldn't we also update
parent->lsn? Otherwise, we might fail to detect a concurrent page split
with the LSN-NSN interlock checks. Or maybe it's correct, and we should
indeed not update the memorized LSN. Or maybe it doesn't matter because
we retry from the parent anyway, thanks to the 'retry_from_parent' flag?
I'm not sure..

I go through the code many times. I found that updating parent->lsn or not
seemd to have no impact. Sorry, I'm not 100% sure.
 

If you're interested to work on this, Tender, maybe you can figure that out?

--
Heikki Linnakangas
Neon (https://neon.tech)


--
Tender Wang
OpenPie:  https://en.openpie.com/