Re: Re: PANIC: invalid index offnum: 186 when processing BRIN indexes in VACUUM

So in a few more runs this morning using Alvaro's simplified test case,
I have seen the following behaviors not previously reported:

1. Crashes in PageIndexTupleOverwrite, which has the same "invalid index
offnum: %u" error report as PageIndexTupleDeleteNoCompact. I note the
same message appears in plain PageIndexTupleDelete as well.
I think we've been too hasty to assume all instances of this came out of
PageIndexTupleDeleteNoCompact.

2. Crashes in the data-insertion process, not only the process running
summarize_range:

#1 0x0000003b78a33c75 in abort () at abort.c:92
#2 0x000000000086e527 in errfinish (dummy=<value optimized out>) at elog.c:557
#3 0x000000000086f334 in elog_finish (elevel=<value optimized out>,
fmt=<value optimized out>) at elog.c:1378
#4 0x000000000075d48f in PageIndexTupleDeleteNoCompact (
rel=<value optimized out>, buf=2772, page=0x7f0188438080 "\002", offnum=39)
at bufpage.c:995
#5 0x0000000000476fd2 in brin_doupdate (idxrel=0x7f0186633e90,
pagesPerRange=1, revmap=0xba, heapBlk=2542, oldbuf=2772, oldoff=39,
origtup=0x2784010, origsz=8, newtup=0x2784098, newsz=400,
samepage=0 '\000') at brin_pageops.c:270
#6 0x0000000000475430 in brininsert (idxRel=0x7f0186633e90,
values=0x7ffce7b827f0, nulls=0x7ffce7b828f0 "", heaptid=0x279fb3c,
heapRel=<value optimized out>, checkUnique=<value optimized out>,
indexInfo=0x279e370) at brin.c:292
#7 0x000000000061da18 in ExecInsertIndexTuples (slot=0x279e638,
tupleid=0x279fb3c, estate=0x279dd10, noDupErr=0 '\000', specConflict=0x0,
arbiterIndexes=0x0) at execIndexing.c:387

The postmaster log for this, with even more debug logging thrown in:

2017-10-31 11:58:03.466 EDT [23506] LOG: summarize_range(brin_test_a_idx,2542,2543) created placeholder at 68,39
2017-10-31 11:58:03.466 EDT [23506] STATEMENT: select brin_summarize_new_values('brin_test_a_idx')
2017-10-31 11:58:03.466 EDT [23506] LOG: brin_doupdate(brin_test_a_idx) at 68,39: getinsertbuffer returned page 70
2017-10-31 11:58:03.466 EDT [23506] STATEMENT: select brin_summarize_new_values('brin_test_a_idx')
2017-10-31 11:58:03.466 EDT [23506] LOG: deleting tuple 39 (of 39) in rel brin_test_a_idx page 68
2017-10-31 11:58:03.466 EDT [23506] STATEMENT: select brin_summarize_new_values('brin_test_a_idx')
2017-10-31 11:58:03.466 EDT [23506] LOG: brin_doupdate(brin_test_a_idx) at 68,39: placed at 70,1
2017-10-31 11:58:03.466 EDT [23506] STATEMENT: select brin_summarize_new_values('brin_test_a_idx')
2017-10-31 11:58:03.466 EDT [23509] LOG: brin_doupdate(brin_test_a_idx) at 68,39: getinsertbuffer returned page 70
2017-10-31 11:58:03.466 EDT [23509] STATEMENT: insert into brin_test values (repeat(chr(ascii('A') + int4(random() * 61)), int4(random() * 200)));
2017-10-31 11:58:03.466 EDT [23509] LOG: deleting tuple 39 (of 38) in rel brin_test_a_idx page 68
2017-10-31 11:58:03.466 EDT [23509] STATEMENT: insert into brin_test values (repeat(chr(ascii('A') + int4(random() * 61)), int4(random() * 200)));
2017-10-31 11:58:03.466 EDT [23509] PANIC: invalid index offnum: 39
2017-10-31 11:58:03.466 EDT [23509] STATEMENT: insert into brin_test values (repeat(chr(ascii('A') + int4(random() * 61)), int4(random() * 200)));
2017-10-31 11:58:03.466 EDT [23506] LOG: summarize_range(brin_test_a_idx,2542,2543): update at 68,39 succeeded
2017-10-31 11:58:03.466 EDT [23506] STATEMENT: select brin_summarize_new_values('brin_test_a_idx')
2017-10-31 11:58:04.517 EDT [23493] LOG: server process (PID 23509) was terminated by signal 6: Aborted

So what evidently happened here is that brininsert decided it needed to
insert into the placeholder tuple that summarize_range had just created,
but by the time it got lock on the buffer, summarize_range had deleted
the placeholder and instead created a new tuple on another page.

HAH: I see how the connection to PageIndexTupleDeleteNoCompact's
change applies. After re-locking the buffer, brin_doupdate tries
to check whether the tuple's been deleted, but it needs to do it
more like this, else it might be accessing off the end of the
lp array:

/*
* Check that the old tuple wasn't updated concurrently: it might have
* moved someplace else entirely ...
*/
- if (!ItemIdIsNormal(oldlp))
+ if (oldoff > PageGetMaxOffsetNumber(oldpage) ||
+ !ItemIdIsNormal(oldlp))
{
LockBuffer(oldbuf, BUFFER_LOCK_UNLOCK);

This is a pre-existing bug, but before 24992c6d, it would only
have manifested in the (very?) unusual corner case that
PageIndexDeleteNoCompact was able to reset the page to empty.

However, when I fix that and then run Alvaro's test case, I get
ERROR: corrupted BRIN index: inconsistent range map
so there's more creepy-crawlies around here somewhere.

I really don't understand how any of this "let's release the buffer
lock and then take it back later" logic is supposed to work reliably.

BTW, while I'm bitching, it seems fairly insane from a concurrency
standpoint that brin_getinsertbuffer is calling RecordPageWithFreeSpace
while holding at least one and possibly two buffer locks. Shouldn't
that be done someplace else?

regards, tom lane