Re: Re: PANIC: invalid index offnum: 186 when processing BRIN indexes in VACUUM
Tom Lane <tgl@sss.pgh.pa.us>
From: Tom Lane <tgl@sss.pgh.pa.us>
To: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Tomas Vondra <tomas.vondra@2ndquadrant.com>,
Michael Paquier <michael.paquier@gmail.com>,
PostgreSQL mailing lists <pgsql-hackers@postgresql.org>
Date: 2017-10-30T22:34:05Z
Lists: pgsql-hackers
Attachments
- hack-to-log-PageIndexTupleDeleteNoCompact.patch (text/x-diff) patch
I wrote: > Hmm. The index offnum being complained of is one past the end of the > lp array. I think I see what about that commit changed the behavior: > the old code for PageIndexDeleteNoCompact never changed the length > of the lp array, except in the corner case where the page is becoming > completely empty. The new code will shorten the lp array (decrease > phdr->pd_lower) if it's told to remove the last item. So if you make > two successive calls specifying the same offnum, and it's the last one > on the page, the second one will fail with the symptoms we see here. > However, so far as I can see, a sequence like that would have failed > before too, just with a different error message, because once the > first call had marked the item unused, the second call would not see > it as a candidate to match. So I'm not quite sure how that's related > ... but it seems like it must be. I'm still confused about why it didn't fail before, but after adding some additional code to log each call of PageIndexTupleDeleteNoCompact, I think I've got a smoking gun: 2017-10-30 18:18:44.321 EDT [10932] LOG: deleting tuple 292 (of 292) in rel brin_test_c_idx page 2 2017-10-30 18:18:44.321 EDT [10932] STATEMENT: vacuum brin_test 2017-10-30 18:18:44.393 EDT [10932] LOG: deleting tuple 292 (of 292) in rel brin_test_d_idx page 2 2017-10-30 18:18:44.393 EDT [10932] STATEMENT: vacuum brin_test 2017-10-30 18:18:53.428 EDT [10932] LOG: deleting tuple 186 (of 186) in rel brin_test_e_idx page 3 2017-10-30 18:18:53.428 EDT [10932] STATEMENT: vacuum brin_test 2017-10-30 18:19:13.794 EDT [10938] LOG: deleting tuple 186 (of 186) in rel brin_test_e_idx page 4 2017-10-30 18:19:13.794 EDT [10938] STATEMENT: insert into brin_test select mod(i,100000)/25, mod(i,100000)/25, mod(i,100000)/25, mod(i,100000)/25, md5((mod(i,100000)/25)::text)::uuid from generate_series(1,100000) s(i) 2017-10-30 18:19:13.795 EDT [10932] LOG: deleting tuple 186 (of 185) in rel brin_test_e_idx page 4 2017-10-30 18:19:13.795 EDT [10932] STATEMENT: vacuum brin_test 2017-10-30 18:19:13.795 EDT [10932] PANIC: invalid index offnum: 186 2017-10-30 18:19:13.795 EDT [10932] STATEMENT: vacuum brin_test So what happened here is that the inserting process decided to summarize concurrently with the VACUUM process, and the inserting process deleted (or maybe just updated/moved?) the placeholder tuple that VACUUM was expecting to delete, and then we get the PANIC because the tuple we're expecting to delete is already gone. So: I put the blame on the fact that summarize_range() thinks that the tuple offset it has for the placeholder tuple is guaranteed to hold good, even across possibly-long intervals where it's holding no lock on the containing buffer. Fixing this without creating new problems is beyond my familiarity with the BRIN code. It looks like it might be nontrivial :-( regards, tom lane
Commits
-
Fix BRIN summarization concurrent with extension
- ec42a1dcb30d 11.0 landed
- cf0612aa2c8f 9.5.10 landed
- bd8e2b3cf4cf 9.6.6 landed
- 37a856567c04 10.1 landed
-
Fix corner-case errors in brin_doupdate().
- 62a16572d571 11.0 landed
- a43cd427e703 9.6.6 landed
- 43276abc6f7e 9.5.10 landed
- 97ba7b8c87e1 10.1 landed
-
Rewrite PageIndexDeleteNoCompact into a form that only deletes 1 tuple.
- 24992c6db9fd 10.0 cited
-
Invent PageIndexTupleOverwrite, and teach BRIN and GiST to use it.
- b1328d78f88c 10.0 cited
-
Close some holes in BRIN page assignment
- ccc4c074994d 9.6.0 cited