pg.ddx.io pgsql-bugs@postgresql.org mailing list archive
help / color / mirror / Atom feedIRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
41+ messages / 4 participants
[nested] [flat]
* IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
@ 2021-06-24 12:59 Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
0 siblings, 2 replies; 41+ messages in thread
From: Heikki Linnakangas @ 2021-06-24 12:59 UTC (permalink / raw)
To: Alexander Korotkov <aekorotkov@gmail.com>; Pawel Kudzia <kudzia@gmail.com>; +Cc: pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
On 17/06/2021 22:49, Tom Lane wrote:
> I wrote:
>> Pawel Kudzia <kudzia@gmail.com> writes:
>>> with help from IRC we've found that decreasing work_mem from 1MB to 256kB
>>> or less makes the problem go away:
>
>> Hmm. So that suggests that the index itself is *not* corrupt,
>> but the problem is associated with a bug in the indexscan
>> algorithms.
>
> After staring at the code I think there is at least one bug, and
> possibly two, in shimTriConsistentFn. That's likely to be implicated
> here because intarray's GIN opclass only provides a bool consistent
> function. I'm not very clear on the circumstances that lead to the scan
> code inventing GIN_MAYBE inputs, so I haven't been able to construct a
> test case.
>
> The definite bug is triggered because intarray relies on the API
> specification that says that if the search mode is
> GIN_SEARCH_MODE_DEFAULT, then the consistentFn will only be called
> when there's at least one TRUE key:
>
> case RTOverlapStrategyNumber:
> /* result is not lossy */
> *recheck = false;
> /* at least one element in check[] is true, so result = true */
> res = true;
> break;
>
> shimTriConsistentFn ignores this and calls it on all-FALSE inputs,
> for which it'll incorrectly get a TRUE result, as it will also for
> all the following checks. The upshot is that shimTriConsistentFn
> will convert any case with a MAYBE input to a hard TRUE result,
> with no recheck requirement. This'd easily explain the reported
> misbehavior.
That's subtle. The documentation says:
> If <literal>*searchMode</literal> is set to
> <literal>GIN_SEARCH_MODE_DEFAULT</literal> (which is the value it is
> initialized to before call), only items that match at least one of
> the returned keys are considered candidate matches.
I guess you can read that as "consistentFn will only be called when
there is at least one matching item", but that didn't occur to me when I
read that at first. But I agree we need to fix shimTriConsistentFn to
respect that.
> The other thing that I'm unsure about, because the code is horribly
> underdocumented, is that it's not very clear whether
> shimTriConsistentFn is accurately converting between the bool and
> the tristate APIs. That's because it's not very clear what the
> tristate API actually *is*. In particular, is the end state of
> key->recheckCurItem meaningful in the tristate case? If it's not,
> then the short-circuit case for no MAYBE inputs is broken, because
> it'll return TRUE when the bool consistentFn is trying to tell us
> to recheck. But if it is meaningful, then the multiway case is broken,
> because it will return the recheckCurItem result set by the last call to
> the bool consistentfn; which might be false even though other calls said
> true. (So in that case I think we'd need "key->recheckCurItem = recheck"
> at the end.) I also wonder how any of that works correctly for real
> triconsistent functions, which don't have access to the recheckCurItem
> flag.
>
> Anyway, I'm punting this to the code authors. I'd like to see
> some comments clarifying what the API really is, not just a
> quick-n-dirty code fix.
I've been trying to create a test case for this, but no luck so far. I
cannot find a codepath that would hit these bugs with the kind of query
that Pawel used. The search condition is very simple: "column &&
'{constant}'", with only one key and one constant to search for. There
are three calls to triConsistentFn:
1. In startScanKey, but that's only reached if (key->nentries > 1), so
not reachable with Pawel's query.
2. In keyGetItem, when haveLossyEntry==true. But AFAICS, haveLossyEntry
is never true with Pawel's query. That would require curItem to be a
lossy pointer, and that in turn can only happen when matchBitmap is
used, and that's only used with partial match queries and with queries
that need a full-index scan.
3. The second call in keyGetItem is reached, but it is only passed
GIN_MAYBE when curItem is lossy. Which isn't possible with this query,
see point 2.
AFAICS the recheckCurItem bug should also not cause wrong results with
that query. I must be missing something.
I could probably construct a test case with a different query, one
involving multiple elements in the search key, but I'd like to have a
solid explanation for the original report.
Pawel, is this a production system, or would it be possible for you to
build from sources with a patch with some extra debugging output?
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-06-24 13:32 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
1 sibling, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-06-24 13:32 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
>
> Pawel, is this a production system, or would it be possible for you to
> build from sources with a patch with some extra debugging output?
>
thank you for looking into it!
it is a production system but we have couple of replicas. when the
problem occurs - it can be reproduced on any replica as well. when
it happens again - i can stop one of replicas, take file level backup
and set up a test machine on which i can try to build PG from source,
including your patch adding extra verbosity.
please note that the last inconsistency was fixed, but i expect that
new one will show up within few days.
greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-05 13:36 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-05 13:36 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
On Thu, Jun 24, 2021 at 3:32 PM Pawel Kudzia <kudzia@gmail.com> wrote:
> > Pawel, is this a production system, or would it be possible for you to
> > build from sources with a patch with some extra debugging output?
> thank you for looking into it!
>
> it is a production system but we have couple of replicas. when the
> problem occurs - it can be reproduced on any replica as well. when
> it happens again - i can stop one of replicas, take file level backup
> and set up a test machine on which i can try to build PG from source,
> including your patch adding extra verbosity.
>
> please note that the last inconsistency was fixed, but i expect that
> new one will show up within few days.
hello again,
i have a consistent file-level backup of postgresql's /var/lib/postgresql +
/etc/postgresql on which i can reproduce the issue reliably. it's on a test
machine where we can put patched version of PG. currently this machine
is using Debian 13.3-1.pgdg100+1.
set enable_seqscan=off;
SELECT entity_id FROM entity WHERE ( attribute_name_ids && '{1737}' )
AND NOT ( (attribute_name_ids||0) && '{1737}') LIMIT 10;
returns me 2 rows while it should return none.
also in this case lowering work_mem from 1MB to 256kB makes fixes the
issue - SELECT returns 0 rows instead of 2.
i'll be happy to run patched version and send you back logs produced by it.
greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-11 18:42 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-11 18:42 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
On 05/07/2021 16:36, Pawel Kudzia wrote:
> i have a consistent file-level backup of postgresql's /var/lib/postgresql +
> /etc/postgresql on which i can reproduce the issue reliably. it's on a test
> machine where we can put patched version of PG. currently this machine
> is using Debian 13.3-1.pgdg100+1.
>
> set enable_seqscan=off;
> SELECT entity_id FROM entity WHERE ( attribute_name_ids && '{1737}' )
> AND NOT ( (attribute_name_ids||0) && '{1737}') LIMIT 10;
>
> returns me 2 rows while it should return none.
>
> also in this case lowering work_mem from 1MB to 256kB makes fixes the
> issue - SELECT returns 0 rows instead of 2.
>
> i'll be happy to run patched version and send you back logs produced by it.
Thanks! Here's a patch that prints lines with "GINBUG:" prefix in the
log. It should apply cleanly to PostgreSQL v13.
This should help to confirm whether the bugs in shimTriConsistentFn that
Tom pointed out are the root cause of this issue. It should also tell us
whether the rows are being returned from the pending-inserts list or the
regular part of the GIN index.
We might need a few iterations to test different theories, but we'll get
there...
- Heikki
Ps. Sorry for the delay, I didn't see you reply until now, it went into
spam folder
Attachments:
trace-gin-consistent-funcs-1.patch (text/x-patch, 2.9K) download
diff --git a/src/backend/access/gin/ginget.c b/src/backend/access/gin/ginget.c
index 2cfccdedcf..5799a96d6c 100644
--- a/src/backend/access/gin/ginget.c
+++ b/src/backend/access/gin/ginget.c
@@ -35,6 +35,21 @@ typedef struct pendingPosition
} pendingPosition;
+static char *
+printEntryRes(GinScanKey key)
+{
+ static char buf[101];
+ int i;
+
+ for (i = 0; i < key->nentries && i < 100; i++)
+ {
+ buf[i] = '0' + key->entryRes[i];
+ }
+ buf[i] = '\0';
+
+ return buf;
+}
+
/*
* Goes to the next page if current offset is outside of bounds
*/
@@ -513,6 +528,8 @@ startScanKey(GinState *ginstate, GinScanOpaque so, GinScanKey key)
key->recheckCurItem = false;
key->isFinished = false;
+ elog(LOG, "GINBUG: startScanKey called: excludeOnly %d nentries %d", key->excludeOnly, key->nentries);
+
/*
* Divide the entries into two distinct sets: required and additional.
* Additional entries are not enough for a match alone, without any items
@@ -557,13 +574,21 @@ startScanKey(GinState *ginstate, GinScanOpaque so, GinScanKey key)
for (i = 0; i < key->nentries - 1; i++)
{
+ GinTernaryValue res;
+ char *debugkey;
+
/* Pass all entries <= i as FALSE, and the rest as MAYBE */
for (j = 0; j <= i; j++)
key->entryRes[entryIndexes[j]] = GIN_FALSE;
for (j = i + 1; j < key->nentries; j++)
key->entryRes[entryIndexes[j]] = GIN_MAYBE;
- if (key->triConsistentFn(key) == GIN_FALSE)
+ debugkey = printEntryRes(key);
+ res = key->triConsistentFn(key);
+
+ elog(LOG, "GINBUG: called triConsistentFn(%s) in startScanKey: %d %d", debugkey, res, key->recheckCurItem);
+
+ if (res == GIN_FALSE)
break;
}
/* i is now the last required entry. */
@@ -1182,8 +1207,11 @@ keyGetItem(GinState *ginstate, MemoryContext tempCtx, GinScanKey key,
if (haveLossyEntry)
{
/* Have lossy-page entries, so see if whole page matches */
+ char *debugkey = printEntryRes(key);
res = key->triConsistentFn(key);
+ elog(LOG, "GINBUG: called triConsistentFn(%s) for lossy entry: %d %d", debugkey, res, key->recheckCurItem);
+
if (res == GIN_TRUE || res == GIN_MAYBE)
{
/* Yes, so clean up ... */
@@ -1230,8 +1258,14 @@ keyGetItem(GinState *ginstate, MemoryContext tempCtx, GinScanKey key,
key->entryRes[i] = GIN_FALSE;
}
+ {
+ char *debugkey = printEntryRes(key);
+
res = key->triConsistentFn(key);
+ elog(LOG, "GINBUG: called triConsistentFn(%s): %d %d", debugkey, res, key->recheckCurItem);
+ }
+
switch (res)
{
case GIN_TRUE:
@@ -1888,8 +1922,14 @@ scanPendingInsert(IndexScanDesc scan, TIDBitmap *tbm, int64 *ntids)
for (i = 0; i < so->nkeys; i++)
{
GinScanKey key = so->keys + i;
+ char *debugkey = printEntryRes(key);
+ bool res;
+
+ res = key->boolConsistentFn(key);
+
+ elog(LOG, "GINBUG: called boolConsistentFn, key %d %s: %d %d", i, debugkey, res, key->recheckCurItem);
- if (!key->boolConsistentFn(key))
+ if (!res)
{
match = false;
break;
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-12 17:24 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-12 17:24 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
On Sun, Jul 11, 2021 at 8:42 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
> On 05/07/2021 16:36, Pawel Kudzia wrote:
> > i have a consistent file-level backup of postgresql's /var/lib/postgresql +
> > /etc/postgresql on which i can reproduce the issue reliably. it's on a test
> > machine where we can put patched version of PG. currently this machine
> > is using Debian 13.3-1.pgdg100+1.
> >
> > set enable_seqscan=off;
> > SELECT entity_id FROM entity WHERE ( attribute_name_ids && '{1737}' )
> > AND NOT ( (attribute_name_ids||0) && '{1737}') LIMIT 10;
> >
> > returns me 2 rows while it should return none.
> >
> > also in this case lowering work_mem from 1MB to 256kB makes fixes the
> > issue - SELECT returns 0 rows instead of 2.
> >
> > i'll be happy to run patched version and send you back logs produced by it.
>
> Thanks! Here's a patch that prints lines with "GINBUG:" prefix in the
> log. It should apply cleanly to PostgreSQL v13.
>
> This should help to confirm whether the bugs in shimTriConsistentFn that
> Tom pointed out are the root cause of this issue. It should also tell us
> whether the rows are being returned from the pending-inserts list or the
> regular part of the GIN index.
>
> We might need a few iterations to test different theories, but we'll get
> there...
>
Heikki - thank you for the patch! it applied cleanly.
i've run these two commands:
SET enable_seqscan=off;
SELECT entity_id FROM entity WHERE ( attribute_name_ids && '{1737}' )
AND NOT ( (attribute_name_ids||0) && '{1737}') LIMIT 10;
and got this in the output:
2021-07-12 07:41:05 UTC LOG: GINBUG: startScanKey called: excludeOnly
0 nentries 1
2021-07-12 07:41:05 UTC STATEMENT: SELECT entity_id FROM entity WHERE
( attribute_name_ids && '{1737}' ) AND NOT ( (attribute_name_ids||0)
&& '{1737}') LIMIT 10;
2021-07-12 07:41:05 UTC LOG: GINBUG: called triConsistentFn(1): 1 0
the "STATEMENT" line is repeated 79586 times, the "GINBUG: called
triConsistentFn" - 79585 times.
there's nothing else in the log besides information about server startup.
i'll be happy to help with the follow up checks.
> Ps. Sorry for the delay, I didn't see you reply until now, it went into
> spam folder
no worries!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-13 22:25 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-13 22:25 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
On 12/07/2021 20:24, Pawel Kudzia wrote:
> i've run these two commands:
>
> SET enable_seqscan=off;
> SELECT entity_id FROM entity WHERE ( attribute_name_ids && '{1737}' )
> AND NOT ( (attribute_name_ids||0) && '{1737}') LIMIT 10;
>
> and got this in the output:
>
> 2021-07-12 07:41:05 UTC LOG: GINBUG: startScanKey called: excludeOnly
> 0 nentries 1
>
> 2021-07-12 07:41:05 UTC STATEMENT: SELECT entity_id FROM entity WHERE
> ( attribute_name_ids && '{1737}' ) AND NOT ( (attribute_name_ids||0)
> && '{1737}') LIMIT 10;
> 2021-07-12 07:41:05 UTC LOG: GINBUG: called triConsistentFn(1): 1 0
>
>
> the "STATEMENT" line is repeated 79586 times, the "GINBUG: called
> triConsistentFn" - 79585 times.
>
> there's nothing else in the log besides information about server startup.
>
> i'll be happy to help with the follow up checks.
Ok, that confirms that it's taking the simple path through
triConsistentFn(), with a single non-lossy key. Also, there don't seem
to be any pending inserts. Now that we've ruled those out, I have no
clue what the problem might be.
Is the data sensitive, or you could you share it? I realize it's a
pretty large database, but if I had a copy I could poke around to look
at the index pages involved here, to see if they're corrupt and how. If
that's possible, you can contact me directly, off-list, to figure the
logistics to send over a copy of the data directory.
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-13 23:02 ` Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Peter Geoghegan @ 2021-07-13 23:02 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Pawel Kudzia <kudzia@gmail.com>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Tue, Jul 13, 2021 at 3:25 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> Is the data sensitive, or you could you share it? I realize it's a
> pretty large database, but if I had a copy I could poke around to look
> at the index pages involved here, to see if they're corrupt and how. If
> that's possible, you can contact me directly, off-list, to figure the
> logistics to send over a copy of the data directory.
Worth noting that the Wiki describes a number two ways to do this when
reporting a bug -- using gdb, and using contrib/pageinspect:
https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#...
--
Peter Geoghegan
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
@ 2021-07-14 14:37 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-14 14:37 UTC (permalink / raw)
To: Peter Geoghegan <pg@bowt.ie>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Wed, Jul 14, 2021 at 1:03 AM Peter Geoghegan <pg@bowt.ie> wrote:
>
> On Tue, Jul 13, 2021 at 3:25 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> > Is the data sensitive, or you could you share it? I realize it's a
> > pretty large database, but if I had a copy I could poke around to look
> > at the index pages involved here, to see if they're corrupt and how. If
> > that's possible, you can contact me directly, off-list, to figure the
> > logistics to send over a copy of the data directory.
>
> Worth noting that the Wiki describes a number two ways to do this when
> reporting a bug -- using gdb, and using contrib/pageinspect:
>
> https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#...
>
Heikki - the data is semi-sensitive. I cannot share the whole table.
I could if it was possible to remove some columns or isolate only
handful of rows.
But - just doing the "vacuum full entity" resolves the original issue
and select returns 0 rows, as it should.
How can I identify relevant pages to make selective dump of them for
you, using method proposed by Peter?
Would interactive session where you can get temporary access to the
server with copy of the database,
to run gdb on it be of any help?
Greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-15 07:04 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-15 07:04 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; Peter Geoghegan <pg@bowt.ie>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 14/07/2021 17:37, Pawel Kudzia wrote:
> Heikki - the data is semi-sensitive. I cannot share the whole table.
> I could if it was possible to remove some columns or isolate only
> handful of rows.
>
> But - just doing the "vacuum full entity" resolves the original issue
> and select returns 0 rows, as it should.
Ok. One idea would be to write a program or extension that overwrites
all the uninteresting columns with zeros.
> How can I identify relevant pages to make selective dump of them for
> you, using method proposed by Peter?
It's a bit hard without knowing which index pages are affected. But the
attached script (dump-gin-page-info.sql) dumps some summary information
about the kind of pages there are. That's a start.
> Would interactive session where you can get temporary access to the
> server with copy of the database,
> to run gdb on it be of any help?
Let's try one thing first: I rebased a patch to add GIN support to the
amcheck extension [1]. I kind of doubt that it will catch the corruption
in this case, but you never know. So please apply the attached
v2-0001-Amcheck-for-GIN-13stable.patch patch. It is the same patch I
posted at [1], but the installation script is slightly different to make
it work on PostgreSQL v13. Then compile install it:
cd contrib/amcheck; make install
Then in psql:
CREATE EXTENSION amcheck;
gin_index_parent_check('entity_attribute_name_ids_gin');
If it reports any inconsistencies, we can try to use pageinspect to
gather further evidence on them.
[1]
https://www.postgresql.org/message-id/a5bc2aad-464b-91bd-061d-28af0f9b634c%40iki.fi
- Heikki
Attachments:
dump-gin-page-info.sql (application/sql, 361B) download
v2-0001-Amcheck-for-GIN-13stable.patch (text/x-patch, 0B) download
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-15 09:38 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-15 09:38 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
> > How can I identify relevant pages to make selective dump of them for
> > you, using method proposed by Peter?
>
> It's a bit hard without knowing which index pages are affected. But the
> attached script (dump-gin-page-info.sql) dumps some summary information
> about the kind of pages there are. That's a start.
I'm attaching output of the proposed commands.
> Let's try one thing first: I rebased a patch to add GIN support to the
> amcheck extension [1]. I kind of doubt that it will catch the corruption
> in this case, but you never know. So please apply the attached
> v2-0001-Amcheck-for-GIN-13stable.patch patch. It is the same patch I
> posted at [1], but the installation script is slightly different to make
> it work on PostgreSQL v13. Then compile install it:
>
> cd contrib/amcheck; make install
>
> Then in psql:
>
> CREATE EXTENSION amcheck;
> gin_index_parent_check('entity_attribute_name_ids_gin');
Sadly i'm getting this when executing CREATE EXTENSION amcheck;
ERROR: extension "amcheck" has no installation script nor update path
for version "1.2.1"
Thank you!
--
regards,
Pawel Kudzia
Attachments:
out.tar.bz2 (application/octet-stream, 1.8M) download
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-15 18:49 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-15 18:49 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 15/07/2021 12:38, Pawel Kudzia wrote:
>>> How can I identify relevant pages to make selective dump of them for
>>> you, using method proposed by Peter?
>>
>> It's a bit hard without knowing which index pages are affected. But the
>> attached script (dump-gin-page-info.sql) dumps some summary information
>> about the kind of pages there are. That's a start.
>
> I'm attaching output of the proposed commands.
Thanks!
>> Let's try one thing first: I rebased a patch to add GIN support to the
>> amcheck extension [1]. I kind of doubt that it will catch the corruption
>> in this case, but you never know. So please apply the attached
>> v2-0001-Amcheck-for-GIN-13stable.patch patch. It is the same patch I
>> posted at [1], but the installation script is slightly different to make
>> it work on PostgreSQL v13. Then compile install it:
>>
>> cd contrib/amcheck; make install
>>
>> Then in psql:
>>
>> CREATE EXTENSION amcheck;
>> gin_index_parent_check('entity_attribute_name_ids_gin');
>
> Sadly i'm getting this when executing CREATE EXTENSION amcheck;
>
> ERROR: extension "amcheck" has no installation script nor update path
> for version "1.2.1"
Hmm, that's odd, it worked for me. Did "make install" copy the
"amcheck--1.2--1.2.1.sql" file to the right place? It should be
installed the same directory as "amcheck.control".
Anyway, let's try a different tack. Here's another debugging patch. It
causes a LOG message to be printed whenever a GIN index page is
accessed, like this:
2021-07-15 21:22:20.119 EEST [972708] LOG: ReadBuffer 1663/12678/27035
read gin blk 0 (ginget.c:1832 scanPendingInsert)
2021-07-15 21:22:20.119 EEST [972708] STATEMENT: explain analyze select
* from test_intarray where a @> '{2}';
2021-07-15 21:22:20.119 EEST [972708] LOG: ReadBuffer 1663/12678/27035
read gin blk 1 (ginbtree.c:89 ginFindLeafPage)
2021-07-15 21:22:20.119 EEST [972708] STATEMENT: explain analyze select
* from test_intarray where a @> '{2}';
Please apply this patch, run the query again, and copy the resulting
log. I'm also interested in the contents of the pages that are accessed,
so if you could then run these commands to dump the contents of those
index pages:
# extract just the block numbers from the log
cat <path to postgres log> | perl -ne '/.*read gin blk (\d+)/ && print
"$1\n" ' | sort -n |uniq > /tmp/blocknums
# dump contents of each of those index pages to '/tmp/block-contents'
psql postgres -c "create temp table blocknums(blknum int); copy
blocknums from '/tmp/blocknums'; copy (select blknum,
get_raw_page('entity_attribute_name_ids_gin', blknum) from blocknums) to
'/tmp/block-contents';"
Please send over the resulting PostgreSQL log, and
'/tmp/block-contents', and I'll take a closer look into the contents to
see if there's something funny. (A private email is OK if you don't feel
comfortable sharing it with the world).
One more thing, please also add the 'ctid' virtual column to the query,
like this:
SELECT ctid, entity_id FROM entity WHERE
( attribute_name_ids && '{1737}' ) AND NOT ( (attribute_name_ids||0)
&& '{1737}') LIMIT 10;
Also, did you happen to keep the WAL log from around the time that the
query started producing wrong results? That would also be useful
evidence for how it got into this situation.
Thanks in advance! We might need a few more round-trips, but we'll get
there.
- Heikki
Attachments:
trace-gin-readbuffer-2.patch (text/x-patch, 2.3K) download
diff --git a/src/backend/access/gin/ginbtree.c b/src/backend/access/gin/ginbtree.c
index 8d08b05f51..8960f2bbf2 100644
--- a/src/backend/access/gin/ginbtree.c
+++ b/src/backend/access/gin/ginbtree.c
@@ -22,6 +22,8 @@
#include "utils/memutils.h"
#include "utils/rel.h"
+#include "access/gin_trace.h"
+
static void ginFindParents(GinBtree btree, GinBtreeStack *stack);
static bool ginPlaceToPage(GinBtree btree, GinBtreeStack *stack,
void *insertdata, BlockNumber updateblkno,
diff --git a/src/backend/access/gin/ginfast.c b/src/backend/access/gin/ginfast.c
index 2e41b34d8d..830c01ec04 100644
--- a/src/backend/access/gin/ginfast.c
+++ b/src/backend/access/gin/ginfast.c
@@ -35,6 +35,8 @@
#include "utils/memutils.h"
#include "utils/rel.h"
+#include "access/gin_trace.h"
+
/* GUC parameter */
int gin_pending_list_limit = 0;
diff --git a/src/backend/access/gin/ginget.c b/src/backend/access/gin/ginget.c
index 2cfccdedcf..a1430a3b08 100644
--- a/src/backend/access/gin/ginget.c
+++ b/src/backend/access/gin/ginget.c
@@ -22,6 +22,8 @@
#include "utils/memutils.h"
#include "utils/rel.h"
+#include "access/gin_trace.h"
+
/* GUC parameter */
int GinFuzzySearchLimit = 0;
diff --git a/src/backend/access/gin/ginutil.c b/src/backend/access/gin/ginutil.c
index a400f1fedb..51d5673d9a 100644
--- a/src/backend/access/gin/ginutil.c
+++ b/src/backend/access/gin/ginutil.c
@@ -29,6 +29,7 @@
#include "utils/index_selfuncs.h"
#include "utils/typcache.h"
+#include "access/gin_trace.h"
/*
* GIN handler function: return IndexAmRoutine with access method parameters
diff --git a/src/include/access/gin_trace.h b/src/include/access/gin_trace.h
new file mode 100644
index 0000000000..d858d5889f
--- /dev/null
+++ b/src/include/access/gin_trace.h
@@ -0,0 +1,16 @@
+
+static inline Buffer
+GinReadBuffer(Relation reln, BlockNumber blockNum,
+ const char *filename, int lineno, const char *funcname)
+{
+ if (reln->rd_rel->relam == GIN_AM_OID)
+ {
+ elog(LOG, "ReadBuffer %u/%u/%u read gin blk %u (%s:%d %s)",
+ (reln)->rd_node.spcNode, (reln)->rd_node.dbNode, (reln)->rd_node.relNode, blockNum,
+ filename, lineno, funcname);
+ }
+ return ReadBuffer(reln, blockNum);
+}
+
+#define ReadBuffer(reln, blockNum) \
+ GinReadBuffer(reln, blockNum, __FILE__, __LINE__, PG_FUNCNAME_MACRO)
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-16 07:06 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-16 07:06 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Thu, Jul 15, 2021 at 8:49 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> On 15/07/2021 12:38, Pawel Kudzia wrote:
> >>> How can I identify relevant pages to make selective dump of them for
> >>> you, using method proposed by Peter?
> >>
> >> It's a bit hard without knowing which index pages are affected. But the
> >> attached script (dump-gin-page-info.sql) dumps some summary information
> >> about the kind of pages there are. That's a start.
> >
> > I'm attaching output of the proposed commands.
>
> Thanks!
>
> >> Let's try one thing first: I rebased a patch to add GIN support to the
> >> amcheck extension [1]. I kind of doubt that it will catch the corruption
> >> in this case, but you never know. So please apply the attached
> >> v2-0001-Amcheck-for-GIN-13stable.patch patch. It is the same patch I
> >> posted at [1], but the installation script is slightly different to make
> >> it work on PostgreSQL v13. Then compile install it:
> >>
> >> cd contrib/amcheck; make install
> >>
> >> Then in psql:
> >>
> >> CREATE EXTENSION amcheck;
> >> gin_index_parent_check('entity_attribute_name_ids_gin');
> >
> > Sadly i'm getting this when executing CREATE EXTENSION amcheck;
> >
> > ERROR: extension "amcheck" has no installation script nor update path
> > for version "1.2.1"
>
> Hmm, that's odd, it worked for me. Did "make install" copy the
> "amcheck--1.2--1.2.1.sql" file to the right place? It should be
> installed the same directory as "amcheck.control".
>
>
thank you for the hint. i've messed up patching. now i can get one step
further:
data=# CREATE EXTENSION amcheck;
CREATE EXTENSION
data=# gin_index_parent_check('entity_attribute_name_ids_gin');
ERROR: syntax error at or near "gin_index_parent_check"
LINE 1: gin_index_parent_check('entity_attribute_name_ids_gin');
^
i've also applied trace-gin-readbuffer-2.patch
> Anyway, let's try a different tack. Here's another debugging patch. It
> causes a LOG message to be printed whenever a GIN index page is
> accessed, like this:
>
> 2021-07-15 21:22:20.119 EEST [972708] LOG: ReadBuffer 1663/12678/27035
> read gin blk 0 (ginget.c:1832 scanPendingInsert)
> 2021-07-15 21:22:20.119 EEST [972708] STATEMENT: explain analyze select
> * from test_intarray where a @> '{2}';
> 2021-07-15 21:22:20.119 EEST [972708] LOG: ReadBuffer 1663/12678/27035
> read gin blk 1 (ginbtree.c:89 ginFindLeafPage)
> 2021-07-15 21:22:20.119 EEST [972708] STATEMENT: explain analyze select
> * from test_intarray where a @> '{2}';
>
> Please apply this patch, run the query again, and copy the resulting
> log.
that'll be the file called "log", send directly to your e-mail address.
> I'm also interested in the contents of the pages that are accessed,
> so if you could then run these commands to dump the contents of those
> index pages:
>
> # extract just the block numbers from the log
> cat <path to postgres log> | perl -ne '/.*read gin blk (\d+)/ && print
> "$1\n" ' | sort -n |uniq > /tmp/blocknums
>
> # dump contents of each of those index pages to '/tmp/block-contents'
> psql postgres -c "create temp table blocknums(blknum int); copy
> blocknums from '/tmp/blocknums'; copy (select blknum,
> get_raw_page('entity_attribute_name_ids_gin', blknum) from blocknums) to
> '/tmp/block-contents';"
>
done, side note - i had to run "create extension pageinspect" and provide
name of my database - "data" rather than "postgres".
Please send over the resulting PostgreSQL log, and
> '/tmp/block-contents', and I'll take a closer look into the contents to
> see if there's something funny. (A private email is OK if you don't feel
> comfortable sharing it with the world).
>
> One more thing, please also add the 'ctid' virtual column to the query,
> like this:
>
> SELECT ctid, entity_id FROM entity WHERE
> ( attribute_name_ids && '{1737}' ) AND NOT ( (attribute_name_ids||0)
> && '{1737}') LIMIT 10;
>
that's how the queries above were run. output:
ctid | entity_id
--------------+-----------
(4002784,1) | 38048120
(4002869,14) | 95333744
(2 rows)
> Also, did you happen to keep the WAL log from around the time that the
> query started producing wrong results? That would also be useful
> evidence for how it got into this situation.
>
sadly i don't. as noted earlier - we've already switched the production
setup so i have no way of leading to corruption again, i only have two
file-level backups of the database with two different inconsistencies in
the SELECTs.
greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-17 20:51 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-17 20:51 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 16/07/2021 10:06, Pawel Kudzia wrote:
>
>
> On Thu, Jul 15, 2021 at 8:49 PM Heikki Linnakangas <hlinnaka@iki.fi
> <mailto:hlinnaka@iki.fi>> wrote:
>
> thank you for the hint. i've messed up patching. now i can get one step
> further:
>
> data=# CREATE EXTENSION amcheck;
> CREATE EXTENSION
> data=# gin_index_parent_check('entity_attribute_name_ids_gin');
> ERROR: Â syntax error at or near "gin_index_parent_check"
> LINE 1: gin_index_parent_check('entity_attribute_name_ids_gin');
> Â Â Â Â ^
Ah, sorry, you need to call it with SELECT, like:
SELECT gin_index_parent_check('entity_attribute_name_ids_gin');
> i've also applied trace-gin-readbuffer-2.patch
Darn, I missed one function that's used to read a page when descending
the GIN tree. That explains the seemingly nonsensical accesses in the
log - the trace left out some crucial accesses.
Attached is a new version of that debugging patch. Please repeat the
same steps as before with this:
1. Apply the patch (remove previous patch first if necessary)
2. Compile Postgres, "make install"
3. Clear the log, start postgres
4. Run the query again:
SELECT ctid, entity_id FROM entity WHERE
( attribute_name_ids && '{1737}' ) AND NOT ( (attribute_name_ids||0)
&& '{1737}') LIMIT 10;
5. Stop the server.
6. Extract the content of the accessed index blocks:
cat <path to postgres log> | perl -ne '/.*read gin blk (\d+)/ && print
"$1\n" ' | sort -n |uniq > /tmp/blocknums
psql data -c "create temp table blocknums(blknum int); copy blocknums
from '/tmp/blocknums'; copy (select blknum,
get_raw_page('entity_attribute_name_ids_gin', blknum) from blocknums) to
'/tmp/block-contents';"
7. Send over /tmp/blocknums, /tmp/block-contents and the postgres log again.
Thank you for your patience!
- Heikki
Attachments:
trace-gin-readbuffer-3.patch (text/x-patch, 2.9K) download
diff --git a/src/backend/access/gin/ginbtree.c b/src/backend/access/gin/ginbtree.c
index 8d08b05f51..8960f2bbf2 100644
--- a/src/backend/access/gin/ginbtree.c
+++ b/src/backend/access/gin/ginbtree.c
@@ -22,6 +22,8 @@
#include "utils/memutils.h"
#include "utils/rel.h"
+#include "access/gin_trace.h"
+
static void ginFindParents(GinBtree btree, GinBtreeStack *stack);
static bool ginPlaceToPage(GinBtree btree, GinBtreeStack *stack,
void *insertdata, BlockNumber updateblkno,
diff --git a/src/backend/access/gin/ginfast.c b/src/backend/access/gin/ginfast.c
index 2e41b34d8d..830c01ec04 100644
--- a/src/backend/access/gin/ginfast.c
+++ b/src/backend/access/gin/ginfast.c
@@ -35,6 +35,8 @@
#include "utils/memutils.h"
#include "utils/rel.h"
+#include "access/gin_trace.h"
+
/* GUC parameter */
int gin_pending_list_limit = 0;
diff --git a/src/backend/access/gin/ginget.c b/src/backend/access/gin/ginget.c
index 2cfccdedcf..a1430a3b08 100644
--- a/src/backend/access/gin/ginget.c
+++ b/src/backend/access/gin/ginget.c
@@ -22,6 +22,8 @@
#include "utils/memutils.h"
#include "utils/rel.h"
+#include "access/gin_trace.h"
+
/* GUC parameter */
int GinFuzzySearchLimit = 0;
diff --git a/src/backend/access/gin/ginutil.c b/src/backend/access/gin/ginutil.c
index a400f1fedb..51d5673d9a 100644
--- a/src/backend/access/gin/ginutil.c
+++ b/src/backend/access/gin/ginutil.c
@@ -29,6 +29,7 @@
#include "utils/index_selfuncs.h"
#include "utils/typcache.h"
+#include "access/gin_trace.h"
/*
* GIN handler function: return IndexAmRoutine with access method parameters
diff --git a/src/include/access/gin_trace.h b/src/include/access/gin_trace.h
new file mode 100644
index 0000000000..808e79a9e1
--- /dev/null
+++ b/src/include/access/gin_trace.h
@@ -0,0 +1,33 @@
+
+static inline Buffer
+GinReadBuffer(Relation reln, BlockNumber blockNum,
+ const char *filename, int lineno, const char *funcname)
+{
+ if (reln->rd_rel->relam == GIN_AM_OID)
+ {
+ elog(LOG, "ReadBuffer %u/%u/%u read gin blk %u (%s:%d %s)",
+ (reln)->rd_node.spcNode, (reln)->rd_node.dbNode, (reln)->rd_node.relNode, blockNum,
+ filename, lineno, funcname);
+ }
+ return ReadBuffer(reln, blockNum);
+}
+
+#define ReadBuffer(reln, blockNum) \
+ GinReadBuffer(reln, blockNum, __FILE__, __LINE__, PG_FUNCNAME_MACRO)
+
+
+static inline Buffer
+GinReleaseAndReadBuffer(Buffer buffer, Relation reln, BlockNumber blockNum,
+ const char *filename, int lineno, const char *funcname)
+{
+ if (reln->rd_rel->relam == GIN_AM_OID)
+ {
+ elog(LOG, "ReleaseAndReadBuffer %u/%u/%u read gin blk %u (%s:%d %s)",
+ (reln)->rd_node.spcNode, (reln)->rd_node.dbNode, (reln)->rd_node.relNode, blockNum,
+ filename, lineno, funcname);
+ }
+ return ReleaseAndReadBuffer(buffer, reln, blockNum);
+}
+
+#define ReleaseAndReadBuffer(buf, reln, blockNum) \
+ GinReleaseAndReadBuffer(buf, reln, blockNum, __FILE__, __LINE__, PG_FUNCNAME_MACRO)
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-18 08:27 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-18 08:27 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Sat, Jul 17, 2021 at 10:51 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
> On 16/07/2021 10:06, Pawel Kudzia wrote:
> >
> >
> > On Thu, Jul 15, 2021 at 8:49 PM Heikki Linnakangas <hlinnaka@iki.fi
> > <mailto:hlinnaka@iki.fi>> wrote:
> >
> > thank you for the hint. i've messed up patching. now i can get one step
> > further:
> >
> > data=# CREATE EXTENSION amcheck;
> > CREATE EXTENSION
> > data=# gin_index_parent_check('entity_attribute_name_ids_gin');
> > ERROR: syntax error at or near "gin_index_parent_check"
> > LINE 1: gin_index_parent_check('entity_attribute_name_ids_gin');
> > ^
>
> Ah, sorry, you need to call it with SELECT, like:
>
> SELECT gin_index_parent_check('entity_attribute_name_ids_gin');
>
That worked. It gave me gin_index_parent_check.txt, attached.
> > i've also applied trace-gin-readbuffer-2.patch
>
> Darn, I missed one function that's used to read a page when descending
> the GIN tree. That explains the seemingly nonsensical accesses in the
> log - the trace left out some crucial accesses.
>
> Attached is a new version of that debugging patch. Please repeat the
> same steps as before with this:
>
> 1. Apply the patch (remove previous patch first if necessary)
>
> 2. Compile Postgres, "make install"
>
> 3. Clear the log, start postgres
>
> 4. Run the query again:
>
> SELECT ctid, entity_id FROM entity WHERE
> ( attribute_name_ids && '{1737}' ) AND NOT ( (attribute_name_ids||0)
> && '{1737}') LIMIT 10;
>
for clarity - i'm also running "set enable_seqscan=off" before that
select to ensure that GIN is used.
SELECT gave me
ctid | entity_id
--------------+-----------
(4002784,1) | 38048120
(4002869,14) | 95333744
(2 rows)
> 5. Stop the server.
>
> 6. Extract the content of the accessed index blocks:
>
> cat <path to postgres log> | perl -ne '/.*read gin blk (\d+)/ && print
> "$1\n" ' | sort -n |uniq > /tmp/blocknums
>
> psql data -c "create temp table blocknums(blknum int); copy blocknums
> from '/tmp/blocknums'; copy (select blknum,
> get_raw_page('entity_attribute_name_ids_gin', blknum) from blocknums) to
> '/tmp/block-contents';"
>
> 7. Send over /tmp/blocknums, /tmp/block-contents and the postgres log again.
>
I'm sending those over directly to your mail.
> Thank you for your patience!
>
Thanks a lot for the investigation!
--
regards,
Pawel Kudzia
Attachments:
gin_index_parent_check.txt (text/plain, 12.9K) download
INFO: key block 144821 offset 1
INFO: key block 237013 offset 9
INFO: key block 340832 offset 5
INFO: key block 460134 offset 7
INFO: key block 465580 offset 2
INFO: key block 474533 offset 3
INFO: key block 481585 offset 4
INFO: key block 484108 offset 5
INFO: key block 487225 offset 14
INFO: key block 500935 offset 11
INFO: key block 513713 offset 3
INFO: key block 522385 offset 4
INFO: key block 527882 offset 2
INFO: key block 583372 offset 5
INFO: key block 596824 offset 4
INFO: key block 603793 offset 2
INFO: key block 612329 offset 5
INFO: key block 619361 offset 9
INFO: key block 624300 offset 8
INFO: key block 630254 offset 6
INFO: key block 634961 offset 4
INFO: key block 638628 offset 3
INFO: key block 643769 offset 8
INFO: key block 652425 offset 8
INFO: key block 675194 offset 9
INFO: key block 691580 offset 1
INFO: key block 698093 offset 4
INFO: key block 711369 offset 9
INFO: key block 716830 offset 2
INFO: key block 722664 offset 9
INFO: key block 735035 offset 5
INFO: key block 751306 offset 15
INFO: key block 754964 offset 16
INFO: key block 759299 offset 8
INFO: key block 763341 offset 20
INFO: key block 772835 offset 3
INFO: key block 778992 offset 4
INFO: key block 783901 offset 4
INFO: key block 794954 offset 1
INFO: key block 835823 offset 5
INFO: key block 848782 offset 6
INFO: key block 862423 offset 4
INFO: key block 873355 offset 6
INFO: key block 880685 offset 6
INFO: key block 901082 offset 4
INFO: key block 906406 offset 7
INFO: key block 924664 offset 5
INFO: key block 928795 offset 9
INFO: key block 930652 offset 3
INFO: key block 932313 offset 1
INFO: key block 933820 offset 3
INFO: key block 937817 offset 10
INFO: key block 942405 offset 8
INFO: key block 946251 offset 4
INFO: key block 949517 offset 6
INFO: key block 952799 offset 5
INFO: key block 956280 offset 1
INFO: key block 958502 offset 1
INFO: key block 961239 offset 7
INFO: key block 966710 offset 9
INFO: key block 971338 offset 6
INFO: key block 976395 offset 9
INFO: key block 983778 offset 9
INFO: key block 998126 offset 4
INFO: key block 1024564 offset 2
INFO: key block 1051220 offset 3
INFO: key block 1064789 offset 2
INFO: key block 1074850 offset 9
INFO: key block 1082096 offset 8
INFO: key block 1093154 offset 4
INFO: key block 1095076 offset 1
INFO: key block 1097224 offset 7
INFO: key block 1154376 offset 3
INFO: key block 1189927 offset 7
INFO: key block 1195175 offset 8
INFO: key block 1204045 offset 3
INFO: key block 1210097 offset 8
INFO: key block 1243548 offset 8
INFO: key block 1281841 offset 4
INFO: key block 1329380 offset 7
INFO: key block 1434257 offset 10
INFO: key block 1470528 offset 2
INFO: key block 1479135 offset 2
INFO: key block 1484672 offset 7
INFO: key block 1488684 offset 38
INFO: key block 1491998 offset 4
INFO: key block 1519727 offset 3
INFO: key block 1641658 offset 3
INFO: key block 1719614 offset 8
INFO: key block 1755869 offset 5
INFO: key block 1784701 offset 18
INFO: key block 1801734 offset 5
INFO: key block 1813745 offset 9
INFO: key block 1816203 offset 9
INFO: key block 1817873 offset 6
INFO: key block 1821466 offset 8
INFO: key block 1823353 offset 2
INFO: key block 1825561 offset 2
INFO: key block 1833785 offset 5
INFO: key block 1850535 offset 6
INFO: key block 1858451 offset 5
INFO: key block 1860563 offset 7
INFO: key block 1863368 offset 6
INFO: key block 1873620 offset 2
INFO: key block 1881159 offset 3
INFO: key block 1903223 offset 4
INFO: key block 1911163 offset 7
INFO: key block 1915947 offset 4
INFO: key block 1927870 offset 8
INFO: key block 1940612 offset 2
INFO: key block 1981318 offset 3
INFO: key block 1993074 offset 10
INFO: key block 1997513 offset 2
INFO: key block 2006226 offset 6
INFO: key block 2056205 offset 1
INFO: key block 2067581 offset 5
INFO: key block 2072362 offset 4
INFO: key block 2077152 offset 3
INFO: key block 2094734 offset 3
INFO: key block 2102335 offset 7
INFO: key block 2107275 offset 6
INFO: key block 2117300 offset 1
INFO: key block 2121212 offset 4
INFO: key block 2127827 offset 2
INFO: key block 2134280 offset 6
INFO: key block 2142409 offset 4
INFO: key block 2147923 offset 3
INFO: key block 2157710 offset 3
INFO: key block 2163270 offset 9
INFO: key block 2168904 offset 4
INFO: key block 2173772 offset 4
INFO: key block 2183328 offset 8
INFO: key block 2201666 offset 2
INFO: key block 2210496 offset 1
INFO: key block 2220681 offset 3
INFO: key block 2255102 offset 13
INFO: key block 2265120 offset 3
INFO: key block 2289012 offset 5
INFO: key block 2292816 offset 2
INFO: key block 2304355 offset 2
INFO: key block 2310760 offset 5
INFO: key block 2314046 offset 3
INFO: key block 2318337 offset 4
INFO: key block 2322348 offset 12
INFO: key block 2329172 offset 6
INFO: key block 2333674 offset 4
INFO: key block 2336125 offset 8
INFO: key block 2345535 offset 6
INFO: key block 2348460 offset 5
INFO: key block 2350654 offset 1
INFO: key block 2353225 offset 22
INFO: key block 2358056 offset 5
INFO: key block 2361102 offset 4
INFO: key block 2364084 offset 2
INFO: key block 2370105 offset 1
INFO: key block 2374401 offset 2
INFO: key block 2377279 offset 7
INFO: key block 2380035 offset 7
INFO: key block 2383010 offset 10
INFO: key block 2386552 offset 3
INFO: key block 2391872 offset 7
INFO: key block 2397350 offset 1
INFO: key block 2401536 offset 6
INFO: key block 2406250 offset 10
INFO: key block 2407148 offset 4
INFO: key block 2411352 offset 9
INFO: key block 2414899 offset 6
INFO: key block 2417738 offset 9
INFO: key block 2418849 offset 7
INFO: key block 2420568 offset 4
INFO: key block 2424125 offset 1
INFO: key block 2428859 offset 3
INFO: key block 2430668 offset 7
INFO: key block 2431288 offset 9
INFO: key block 2432437 offset 10
INFO: key block 2435693 offset 10
INFO: key block 2437998 offset 36
INFO: key block 2440375 offset 2
INFO: key block 2444636 offset 9
INFO: key block 2445981 offset 9
INFO: key block 2450266 offset 1
INFO: key block 2453169 offset 6
INFO: key block 2457021 offset 5
INFO: key block 2458047 offset 1
INFO: key block 2459256 offset 17
INFO: key block 2461592 offset 5
INFO: key block 2463693 offset 3
INFO: key block 2466845 offset 5
INFO: key block 2469255 offset 6
INFO: key block 2471443 offset 1
INFO: key block 2475938 offset 5
INFO: key block 2478751 offset 4
INFO: key block 2479884 offset 12
INFO: key block 2481058 offset 8
INFO: key block 2484018 offset 2
INFO: key block 2496522 offset 3
INFO: key block 2515261 offset 10
INFO: key block 2516080 offset 6
INFO: key block 2516573 offset 5
INFO: key block 2517050 offset 8
INFO: key block 2518611 offset 10
INFO: key block 2520918 offset 7
INFO: key block 2527236 offset 2
INFO: key block 2530824 offset 2
INFO: key block 2536367 offset 9
INFO: key block 2540768 offset 7
INFO: key block 2544416 offset 7
INFO: key block 2547843 offset 1
INFO: key block 2812666 offset 7
INFO: key block 2860112 offset 1
INFO: key block 2886128 offset 3
INFO: key block 2907482 offset 1
INFO: key block 2941307 offset 3
INFO: key block 2947826 offset 10
INFO: key block 3162404 offset 2
INFO: key block 3402164 offset 9
INFO: key block 3418065 offset 10
INFO: key block 3419489 offset 8
INFO: key block 3421276 offset 2
INFO: key block 3422192 offset 3
INFO: key block 3424369 offset 8
INFO: key block 3426761 offset 6
INFO: key block 3431389 offset 8
INFO: key block 3432587 offset 5
INFO: key block 3434507 offset 2
INFO: key block 3437591 offset 5
INFO: key block 3438361 offset 5
INFO: key block 3439311 offset 7
INFO: key block 3440362 offset 5
INFO: key block 3441450 offset 8
INFO: key block 3442493 offset 6
INFO: key block 3443678 offset 9
INFO: key block 3444631 offset 1
INFO: key block 3445538 offset 5
INFO: key block 3446709 offset 9
INFO: key block 3447754 offset 9
INFO: key block 3448631 offset 7
INFO: key block 3449876 offset 2
INFO: key block 3451177 offset 2
INFO: key block 3452198 offset 10
INFO: key block 3453538 offset 9
INFO: key block 3454401 offset 5
INFO: key block 3458250 offset 8
INFO: key block 3460905 offset 9
INFO: key block 3461749 offset 2
INFO: key block 3462652 offset 4
INFO: key block 3463491 offset 8
INFO: key block 3464311 offset 5
INFO: key block 3465327 offset 4
INFO: key block 3466313 offset 3
INFO: key block 3467139 offset 4
INFO: key block 3511674 offset 3
INFO: key block 3596322 offset 4
INFO: key block 3727742 offset 6
INFO: key block 3731506 offset 7
INFO: key block 3733153 offset 10
INFO: key block 3736532 offset 5
INFO: key block 3741644 offset 10
INFO: key block 3744691 offset 6
INFO: key block 3745814 offset 1
INFO: key block 3746472 offset 8
INFO: key block 3746854 offset 4
INFO: key block 3748230 offset 3
INFO: key block 3749249 offset 3
INFO: key block 3750247 offset 3
INFO: key block 3751104 offset 7
INFO: key block 3752340 offset 4
INFO: key block 3754145 offset 6
INFO: key block 3755421 offset 2
INFO: key block 3756573 offset 8
INFO: key block 3757768 offset 2
INFO: key block 3758519 offset 5
INFO: key block 3759295 offset 3
INFO: key block 3760266 offset 11
INFO: key block 3761167 offset 2
INFO: key block 3762345 offset 3
INFO: key block 3763392 offset 6
INFO: key block 3764814 offset 5
INFO: key block 3765924 offset 9
INFO: key block 3767086 offset 9
INFO: key block 3770198 offset 6
INFO: key block 3772686 offset 3
INFO: key block 3774102 offset 9
INFO: key block 3775571 offset 5
INFO: key block 3776913 offset 9
INFO: key block 3777927 offset 9
INFO: key block 3779387 offset 6
INFO: key block 3780730 offset 3
INFO: key block 3781769 offset 6
INFO: key block 3803651 offset 8
INFO: key block 3808478 offset 2
INFO: key block 3809516 offset 9
INFO: key block 3811225 offset 8
INFO: key block 3812417 offset 9
INFO: key block 3813347 offset 3
INFO: key block 3813923 offset 7
INFO: key block 3815175 offset 3
INFO: key block 3815793 offset 1
INFO: key block 3820127 offset 8
INFO: key block 3822191 offset 5
INFO: key block 3823487 offset 4
INFO: key block 3825255 offset 2
INFO: key block 3826802 offset 13
INFO: key block 3828124 offset 9
INFO: key block 3837568 offset 6
INFO: key block 3839187 offset 6
INFO: key block 3840541 offset 2
INFO: key block 3841418 offset 6
INFO: key block 3841987 offset 2
INFO: key block 3842447 offset 7
INFO: key block 3843464 offset 2
INFO: key block 3844810 offset 6
INFO: key block 3846204 offset 10
INFO: key block 3848447 offset 8
INFO: key block 3850809 offset 13
INFO: key block 3852913 offset 5
INFO: key block 3854790 offset 5
INFO: key block 3859329 offset 1
INFO: key block 3865728 offset 2
INFO: key block 3866254 offset 7
INFO: key block 3866727 offset 5
INFO: key block 3867191 offset 7
INFO: key block 3867655 offset 9
INFO: key block 3868115 offset 4
INFO: key block 3868580 offset 9
INFO: key block 3869075 offset 1
INFO: key block 3870233 offset 6
INFO: key block 3871114 offset 9
INFO: key block 3871906 offset 8
INFO: key block 3872681 offset 3
INFO: key block 3873126 offset 8
INFO: key block 3873573 offset 7
INFO: key block 3874281 offset 5
INFO: key block 3874905 offset 2
INFO: key block 3875409 offset 9
INFO: key block 3876085 offset 4
INFO: key block 3876695 offset 9
INFO: key block 3877139 offset 1
INFO: key block 3877600 offset 1
INFO: key block 3878122 offset 5
INFO: key block 3878541 offset 4
INFO: key block 3879206 offset 7
INFO: key block 3879859 offset 1
INFO: key block 3880800 offset 6
INFO: key block 3881327 offset 7
INFO: key block 3881778 offset 9
INFO: key block 3882496 offset 7
INFO: key block 3883163 offset 4
INFO: key block 3884158 offset 3
INFO: key block 3884635 offset 1
INFO: key block 3885112 offset 9
INFO: key block 3885891 offset 7
INFO: key block 3888521 offset 7
INFO: key block 3890471 offset 1
INFO: key block 3891422 offset 1
INFO: key block 3892215 offset 9
INFO: key block 3892987 offset 10
INFO: key block 3893637 offset 6
INFO: key block 3895972 offset 2
INFO: key block 3896578 offset 9
INFO: key block 3901003 offset 3
INFO: key block 3901960 offset 5
INFO: key block 3902769 offset 9
INFO: key block 3903894 offset 6
INFO: key block 3904938 offset 7
INFO: key block 3905781 offset 6
INFO: key block 3906526 offset 1
INFO: key block 3907353 offset 3
INFO: key block 3908034 offset 4
INFO: key block 3908909 offset 6
INFO: key block 3909812 offset 3
INFO: key block 3910574 offset 5
INFO: key block 3911322 offset 6
INFO: key block 3912134 offset 3
INFO: key block 3913025 offset 9
INFO: key block 3913788 offset 9
INFO: key block 3914568 offset 7
INFO: key block 3915334 offset 8
INFO: key block 3916015 offset 8
INFO: key block 3917951 offset 3
INFO: key block 3918802 offset 7
INFO: key block 3919569 offset 2
INFO: key block 3920368 offset 9
INFO: key block 3921060 offset 1
INFO: key block 3921636 offset 9
INFO: key block 4294902146 offset 1
ERROR: index "entity_attribute_name_ids_gin": tid exceeds parent's high key in postingTree leaf on block 321746
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-20 11:55 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-20 11:55 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 18/07/2021 11:27, Pawel Kudzia wrote:
> I'm sending those over directly to your mail.
Thanks! I looked through those logs, and I'm now not seeing anything
wrong with the pages involved. The query first scans the pending list,
and doesn't find any matches there. It then descends the entry tree,
finds pointer to a posting tree for id 1373, then scans the posting
tree. For some reason, the TIDs of those offending rows, (4002784,1) and
(4002869,14) are in the posting tree for key '1373', even though the
heap tuples don't contain that key. Both of those TIDs are in the same
TID list, on page 255179:
> postgres=# select * from (select blknum, ((gin_leafpage_items(content)).*) from ginblocks where blknum=255179) x where tids::text like '%(4002869,14)%';
> blknum | first_tid | nbytes |
> tids
>
>
> --------+--------------+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> -------------------------------------------------------------------------------------------
> 255179 | (4002720,16) | 87 | {"(4002720,16)","(4002721,3)","(4002723,5)","(4002739,11)","(4002743,14)","(4002744,2)","(4002784,1)","(4002784,10)","(4002790,46)","(4002790,47)","(4002792
> ,22)","(4002792,23)","(4002792,24)","(4002796,22)","(4002798,2)","(4002800,7)","(4002802,27)","(4002802,28)","(4002803,22)","(4002805,28)","(4002816,13)","(4002817,19)","(4002820,2)","(40028
> 25,17)","(4002854,7)","(4002855,13)","(4002855,14)","(4002869,14)","(4006217,3)","(4006217,11)","(4006307,11)","(4006330,4)","(4006330,8)","(4006331,6)","(4006332,9)","(4006332,10)","(400633
> 3,9)","(4006335,2)","(4006338,1)","(4006342,7)","(4006343,5)","(4006407,2)","(4008912,2)"}
> (1 row)
I've used pg_filedump and pageinspect on all of the pages on the path to
this entry, but I don't see anything wrong with the index.
So how did it end up like that? I'm afraid I have no clue :-(. Peter's
hunch that it's some bad interaction between deleted pages and the
pending list sounds plausible, but looking at the code, I don't see any
concrete bugs like that.
We have one more lead that we haven't fully explored: amcheck reported
this error:
ERROR: index "entity_attribute_name_ids_gin": tid exceeds parent's high
key in postingTree leaf on block 321746
Give that the GIN amheck patch is still very experimental, that could
well be a bug in amcheck instead of real corruption. Also, that error
was *not* in the posting tree for key '1373'. I hacked amcheck on my
laptop to run only on the posting tree or '1373', and it didn't find any
errors there.
But let's check it out. I modified 'amcheck' to print more information.
I also changed it so that it doesn't stop at the first error, but keeps
going, and reports all issues as warnings.
Pawel: Could you try the attached version of amcheck? Please apply the
attached patch (you'll have to un-apply the previous version or start
from a clean source tree), run "SELECT
gin_index_parent_check('entity_attribute_name_ids_gin');" again, and
send over the result? It should print a bunch of INFOs and WARNINGs to
the client's stderr, so a good way to capture that is something like this:
psql -c "select
gin_index_parent_check('entity_attribute_name_ids_gin');" 2> amcheck-log
Let's see if that reveals something interesting. If not, what can we do
next?
1. Let's fix the issues with the triconsistent functions that we
discussed earlier. They don't explain what we're seeing here, but should
be cleaned up nevertheless.
2. Let's add more sanity checks wherever we read a GIN page, to check
that it's of the expected kind. Again we have no theory on what sequence
of events could cause this, but having more sanity checks seems like a
good idea in any case.
3. Run the test case again and wait for the issue to re-appear. This
time, let's try to capture the WAL, so that we can trace back the
modifications to the pages that lead to the situation.
Any other ideas?
- Heikki
Attachments:
v3-0001-Amcheck-for-GIN-13stable.patch (text/x-patch, 0B) download
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-20 12:22 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-20 12:22 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Tue, Jul 20, 2021 at 1:55 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
[..]
>
>
> Pawel: Could you try the attached version of amcheck? Please apply the
> attached patch (you'll have to un-apply the previous version or start
> from a clean source tree), run "SELECT
> gin_index_parent_check('entity_attribute_name_ids_gin');" again, and
> send over the result? It should print a bunch of INFOs and WARNINGs to
> the client's stderr, so a good way to capture that is something like this:
>
> psql -c "select
> gin_index_parent_check('entity_attribute_name_ids_gin');" 2> amcheck-log
>
i'm attaching log of postgresql generated while running the command
above and amcheck-log.
thanks a lot!
--
regards,
Pawel Kudzia
Attachments:
log (application/octet-stream, 38.3K) download
amcheck-log (application/octet-stream, 164.6K) download
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-20 15:34 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-21 10:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 2 replies; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-20 15:34 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 20/07/2021 15:22, Pawel Kudzia wrote:
> On Tue, Jul 20, 2021 at 1:55 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>> Pawel: Could you try the attached version of amcheck? Please apply the
>> attached patch (you'll have to un-apply the previous version or start
>> from a clean source tree), run "SELECT
>> gin_index_parent_check('entity_attribute_name_ids_gin');" again, and
>> send over the result? It should print a bunch of INFOs and WARNINGs to
>> the client's stderr, so a good way to capture that is something like this:
>>
>> psql -c "select
>> gin_index_parent_check('entity_attribute_name_ids_gin');" 2> amcheck-log
>>
>
> i'm attaching log of postgresql generated while running the command
> above and amcheck-log.
>
> thanks a lot!
Great! So it's reporting two kinds of issues. First this:
WARNING: index "entity_attribute_name_ids_gin": tid exceeds parent's
high key in postingTree leaf on block 343573
I looked at the amcheck code again, and that is in fact bogus; there is
nothing wrong with the high keys, but there is a memory management bug
in the amcheck patch that's causing it.
The other error it complains about looks like this:
...
INFO: key (1743225, 6) -> 363962
INFO: key (1746295, 15) -> 341281
INFO: key (1747712, 12) -> 343607
INFO: key (1749215, 4) -> 376056
INFO: key (262563, 1) -> 11547
INFO: key (3906513777, 43269) -> 31653888
INFO: key (536354808, 8196) -> 4432
ERROR: index "entity_attribute_name_ids_gin" has wrong tuple order in
posting tree, block 371806, offset 818
Looking at the amcheck code for that check, that's a false alarm too.
amcheck is calculating the size of this array incorrectly, thinking that
there are more entries on the page than there really are. The entries
above up to (1749215, 4) are valid, but the rest are not real entries,
just amcheck's misinterpretation. Unfortunately 'amcheck' stopped at
that error again.
Sigh. I fixed those issues in amcheck again. And also added some more
checks on the high keys. At least we're making the amcheck patch better,
even if we're not any wiser about the original issue...
Pawel: Can you test once again with the attached amcheck version?
- Heikki
Attachments:
v4-0001-Amcheck-for-GIN-13stable.patch (text/x-patch, 0B) download
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-21 10:49 ` Pawel Kudzia <kudzia@gmail.com>
1 sibling, 0 replies; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-21 10:49 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Tue, Jul 20, 2021 at 5:34 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
[..]
>
> Looking at the amcheck code for that check, that's a false alarm too.
> amcheck is calculating the size of this array incorrectly, thinking that
> there are more entries on the page than there really are. The entries
> above up to (1749215, 4) are valid, but the rest are not real entries,
> just amcheck's misinterpretation. Unfortunately 'amcheck' stopped at
> that error again.
>
> Sigh. I fixed those issues in amcheck again. And also added some more
> checks on the high keys. At least we're making the amcheck patch better,
> even if we're not any wiser about the original issue...
>
> Pawel: Can you test once again with the attached amcheck version?
patch v4-0001-Amcheck-for-GIN-13stable.patch applied to
postgresql-13_13.3.orig.tar.bz2
since the compressed logs are quite large - i've sent them directly to Heikki.
i've executing "select
gin_index_parent_check('entity_attribute_name_ids_gin');" took
considerably longer this time and it ended with :
[524767.920498] postgres[29716]: segfault at fffffffffffffffe ip
00007f214c20a2d8 sp 00007ffe2a5fd040 error 5 in
amcheck.so[7f214c209000+6000]
[524767.920521] Code: 00 00 41 0f b7 4e 04 41 8b 56 0c 41 8b 76 10 49
89 c1 48 8d 04 40 c1 e1 10 45 0f b7 46 08 48 8d 7c 43 fa 41 0f b7 46
06 09 c1 <0f> b7 47 04 50 0f b7 07 0f b7 7f 02 c1 e0 10 09 f8 50 0f b7
43 04
>
> - Heikki
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-22 07:25 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
1 sibling, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-22 07:25 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 20/07/2021 18:58, Pawel Kudzia wrote:
> On Tue, Jul 20, 2021 at 5:34 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>> Pawel: Can you test once again with the attached amcheck version?
>
> patch v4-0001-Amcheck-for-GIN-13stable.patch applied to
> postgresql-13_13.3.orig.tar.bz2
> attached - log and result of the check.
>
> executing "select
> gin_index_parent_check('entity_attribute_name_ids_gin');" took
> considerably longer this time and it ended with :
>
> [524767.920498] postgres[29716]: segfault at fffffffffffffffe ip
> 00007f214c20a2d8 sp 00007ffe2a5fd040 error 5 in
> amcheck.so[7f214c209000+6000]
> [524767.920521] Code: 00 00 41 0f b7 4e 04 41 8b 56 0c 41 8b 76 10 49
> 89 c1 48 8d 04 40 c1 e1 10 45 0f b7 46 08 48 8d 7c 43 fa 41 0f b7 46
> 06 09 c1 <0f> b7 47 04 50 0f b7 07 0f b7 7f 02 c1 e0 10 09 f8 50 0f b7
> 43 04
Hmph, another set of bugs in the amcheck patch. It didn't handle empty
entry tree items, nor empty posting tree pages. And there was another
bug, which caused it to scan entry tree pages multiple times; that's why
the same WARNING was printed multiple times.
Fixed those bugs, new patch version attached. Pawel, can you test this
again, please? At this point, I'm pretty sure this isn't going to reveal
any more information about the original problem, but at least we're
ironing out bugs from the 'amcheck' patch..
I'm grasping at straws here, but here's one more thing we could try: the
query returned these incorrect tuples:
ctid | entity_id
--------------+-----------
(4002784,1) | 38048120
(4002869,14) | 95333744
(2 rows)
We know those entries are in the GIN index with key '1373', when they
shouldn't be. But I wonder if the correct keys for those tuples are
present? Pawel, can you try this, please:
-- persuade planner to use a bitmap index scan
set enable_seqscan=off;
set enable_tidscan=off;
-- avoid lossy bitmaps
set work_mem='1GB';
-- Explain analyze first to check it's using a bitmap index scan and
-- no lossy pages.
explain analyze
SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
'{38048120}' and ctid='(4002784,1)';
SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
'{38048120}' and ctid='(4002784,1)';
explain analyze
SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
'{95333744}' and ctid='(4002869,14)';
SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
'{95333744}' and ctid='(4002869,14)';
- Heikki
Attachments:
v5-0001-Amcheck-for-GIN-13stable.patch (text/x-patch, 0B) download
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-22 09:07 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-22 09:08 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 2 replies; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-22 09:07 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Thu, Jul 22, 2021 at 9:25 AM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
> On 20/07/2021 18:58, Pawel Kudzia wrote:
> > On Tue, Jul 20, 2021 at 5:34 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> >> Pawel: Can you test once again with the attached amcheck version?
> >
> > patch v4-0001-Amcheck-for-GIN-13stable.patch applied to
> > postgresql-13_13.3.orig.tar.bz2
> > attached - log and result of the check.
> >
> > executing "select
> > gin_index_parent_check('entity_attribute_name_ids_gin');" took
> > considerably longer this time and it ended with :
> >
> > [524767.920498] postgres[29716]: segfault at fffffffffffffffe ip
> > 00007f214c20a2d8 sp 00007ffe2a5fd040 error 5 in
> > amcheck.so[7f214c209000+6000]
> > [524767.920521] Code: 00 00 41 0f b7 4e 04 41 8b 56 0c 41 8b 76 10 49
> > 89 c1 48 8d 04 40 c1 e1 10 45 0f b7 46 08 48 8d 7c 43 fa 41 0f b7 46
> > 06 09 c1 <0f> b7 47 04 50 0f b7 07 0f b7 7f 02 c1 e0 10 09 f8 50 0f b7
> > 43 04
>
> Hmph, another set of bugs in the amcheck patch. It didn't handle empty
> entry tree items, nor empty posting tree pages. And there was another
> bug, which caused it to scan entry tree pages multiple times; that's why
> the same WARNING was printed multiple times.
>
> Fixed those bugs, new patch version attached. Pawel, can you test this
> again, please? At this point, I'm pretty sure this isn't going to reveal
> any more information about the original problem, but at least we're
> ironing out bugs from the 'amcheck' patch..
thank you for the next patch Heikki!
no crash this time! i'm sending a message in a separate mail since i'm
not sure if it'll pass through attachment size limit that's applied
for the list.
> I'm grasping at straws here, but here's one more thing we could try: the
> query returned these incorrect tuples:
>
> ctid | entity_id
> --------------+-----------
> (4002784,1) | 38048120
> (4002869,14) | 95333744
> (2 rows)
>
> We know those entries are in the GIN index with key '1373', when they
> shouldn't be. But I wonder if the correct keys for those tuples are
> present? Pawel, can you try this, please:
>
> -- persuade planner to use a bitmap index scan
> set enable_seqscan=off;
> set enable_tidscan=off;
> -- avoid lossy bitmaps
> set work_mem='1GB';
>
> -- Explain analyze first to check it's using a bitmap index scan and
> -- no lossy pages.
> explain analyze
> SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
> '{38048120}' and ctid='(4002784,1)';
> SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
> '{38048120}' and ctid='(4002784,1)';
>
> explain analyze
> SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
> '{95333744}' and ctid='(4002869,14)';
> SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
> '{95333744}' and ctid='(4002869,14)';
data=# explain analyze SELECT ctid, entity_id FROM entity WHERE
attribute_name_ids && '{38048120}' and ctid='(4002784,1)';
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on entity (cost=72.70..3366.69 rows=1 width=14)
(actual time=42.995..42.998 rows=0 loops=1)
Recheck Cond: (attribute_name_ids && '{38048120}'::integer[])
Filter: (ctid = '(4002784,1)'::tid)
-> Bitmap Index Scan on entity_attribute_name_ids_gin
(cost=0.00..72.70 rows=33055 width=0) (actual time=42.989..42.990
rows=0 loops=1)
Index Cond: (attribute_name_ids && '{38048120}'::integer[])
Planning Time: 18.912 ms
Execution Time: 43.515 ms
(7 rows)
data=# SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
'{38048120}' and ctid='(4002784,1)';
ctid | entity_id
------+-----------
(0 rows)
data=# explain analyze SELECT ctid, entity_id FROM entity WHERE
attribute_name_ids && '{95333744}' and ctid='(4002869,14)';
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on entity (cost=72.70..3366.69 rows=1 width=14)
(actual time=2.552..2.554 rows=0 loops=1)
Recheck Cond: (attribute_name_ids && '{95333744}'::integer[])
Filter: (ctid = '(4002869,14)'::tid)
-> Bitmap Index Scan on entity_attribute_name_ids_gin
(cost=0.00..72.70 rows=33055 width=0) (actual time=2.543..2.544 rows=0
loops=1)
Index Cond: (attribute_name_ids && '{95333744}'::integer[])
Planning Time: 0.193 ms
Execution Time: 2.594 ms
(7 rows)
data=# SELECT ctid, entity_id FROM entity WHERE attribute_name_ids &&
'{95333744}' and ctid='(4002869,14)';
ctid | entity_id
------+-----------
(0 rows)
>
> - Heikki
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-23 13:46 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
1 sibling, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-23 13:46 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 22/07/2021 12:07, Pawel Kudzia wrote:
> On Thu, Jul 22, 2021 at 9:25 AM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>>
>> Fixed those bugs, new patch version attached. Pawel, can you test this
>> again, please? At this point, I'm pretty sure this isn't going to reveal
>> any more information about the original problem, but at least we're
>> ironing out bugs from the 'amcheck' patch..
>
> thank you for the next patch Heikki!
> no crash this time! i'm sending a message in a separate mail since i'm
> not sure if it'll pass through attachment size limit that's applied
> for the list.
Thanks! So looking at the log, amcheck is not reporting any more problems.
>> I'm grasping at straws here, but here's one more thing we could try: the
>> query returned these incorrect tuples:
>>
>> ctid | entity_id
>> --------------+-----------
>> (4002784,1) | 38048120
>> (4002869,14) | 95333744
>> (2 rows)
>>
>> We know those entries are in the GIN index with key '1373', when they
>> shouldn't be. But I wonder if the correct keys for those tuples are
>> present? Pawel, can you try this, please:
>
> [queries with nore rows returned]
Ok, so the index is missing entries for the correct key. Looks like the
index entries were inserted into the wrong subtree, under wrong key. But
*how* did that happen? I'm out of ideas, I'm afraid :-(.
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-23 15:04 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-23 21:47 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 19:08 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 2 replies; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-23 15:04 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Fri, Jul 23, 2021 at 3:46 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
> On 22/07/2021 12:07, Pawel Kudzia wrote:
> > On Thu, Jul 22, 2021 at 9:25 AM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> >>
> >> Fixed those bugs, new patch version attached. Pawel, can you test this
> >> again, please? At this point, I'm pretty sure this isn't going to reveal
> >> any more information about the original problem, but at least we're
> >> ironing out bugs from the 'amcheck' patch..
> >
> > thank you for the next patch Heikki!
> > no crash this time! i'm sending a message in a separate mail since i'm
> > not sure if it'll pass through attachment size limit that's applied
> > for the list.
>
> Thanks! So looking at the log, amcheck is not reporting any more problems.
>
> >> I'm grasping at straws here, but here's one more thing we could try: the
> >> query returned these incorrect tuples:
> >>
> >> ctid | entity_id
> >> --------------+-----------
> >> (4002784,1) | 38048120
> >> (4002869,14) | 95333744
> >> (2 rows)
> >>
> >> We know those entries are in the GIN index with key '1373', when they
> >> shouldn't be. But I wonder if the correct keys for those tuples are
> >> present? Pawel, can you try this, please:
> >
> > [queries with nore rows returned]
>
> Ok, so the index is missing entries for the correct key. Looks like the
> index entries were inserted into the wrong subtree, under wrong key. But
> *how* did that happen? I'm out of ideas, I'm afraid :-(.
Thanks a lot for your patience and multiple patches that you've
provided. Please pardon my ignorance - I don't have low-level
understanding of how the query is being executed - but are you sure
that index is missing entries and not the other way around - that it
has too many entries?
To recap - SELECT, answered based on the GIN, reports rows that
actually do not match the criteria provided in WHERE. Just lowering
work_mem makes the problem go away, whith GIN still being used.
Greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-23 21:47 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 20:14 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
1 sibling, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-23 21:47 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org, Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 23 July 2021 18:04:50 EEST, Pawel Kudzia <kudzia@gmail.com> wrote:
>On Fri, Jul 23, 2021 at 3:46 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>>
>> Ok, so the index is missing entries for the correct key. Looks like the
>> index entries were inserted into the wrong subtree, under wrong key. But
>> *how* did that happen? I'm out of ideas, I'm afraid :-(.
Can you tell more about the workload? What INSERT/UPDATE/DELETE commands do you run? How many concurrent clients? Do you run vacuum manually or how often does autovacuum kick in? How long did it take for the problem to appear? What queries did you run to find the corruption, and how often?
I know it's a big ask, but would it be possible to simplify the test case further, to make it reproduce faster? Ideally as a self-contained test script with any sensitive data removed.
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 21:47 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-25 20:14 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-25 20:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
0 siblings, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-25 20:14 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; Tom Lane <tgl@sss.pgh.pa.us>
On Fri, Jul 23, 2021 at 11:47 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
> On 23 July 2021 18:04:50 EEST, Pawel Kudzia <kudzia@gmail.com> wrote:
> >On Fri, Jul 23, 2021 at 3:46 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> >>
> >> Ok, so the index is missing entries for the correct key. Looks like the
> >> index entries were inserted into the wrong subtree, under wrong key. But
> >> *how* did that happen? I'm out of ideas, I'm afraid :-(.
>
> Can you tell more about the workload? What INSERT/UPDATE/DELETE commands do you run? How many concurrent clients? Do you run vacuum manually or how often does autovacuum kick in? How long did it take for the problem to appear? What queries did you run to find the corruption, and how often?
>
It's a mix with low percentage of simple INSERT INTO entity [
inserting single row within a transaction ], DELETE FROM entity [
deleting single row, selected by primary key ] and high number of
UPDATE entity SET .. WHERE primname=?.
There are few millions such updates a day. Single transaction has just
one such update, update sets most of the table columns although in
fact most of their values remain unchanged.
Concurrency level - less than 50 parallel connections.
Vacuum is run manually extremely rarely [ maybe 2-3x a year ].
Based on recent logs - autovacuum happens every ~ 7 days.
Problem was discovered by coincidence - one of users noticed incorrect
results returned, this provoked me to run a script that hammered
database every hour with set of queries in this form:
SELECT primname FROM entity WHERE ( attribute_name_ids && '{{$ani}}' )
AND NOT ( (attribute_name_ids||0) && '{{$ani}}')
It would discover ~ 1-5 problematic entries each week, but there were
periods of few weeks where new problems were not found [ note that
this does not mean there were no such problems, i was hammering only
one of GIN columns - where i had smallest universe of values to
iterate over ].
> I know it's a big ask, but would it be possible to simplify the test case further, to make it reproduce faster? Ideally as a self-contained test script with any sensitive data removed.
>
Sadly - I've put quite a lot of effort to reproduce the issue in test
environment and was never able to do it. Problem occured on the
production only, after prolonged execution of live update traffic.
Note that in the I've moved database to another physical server to
eliminate potential hardware malfunction - that did not help, problem
continued to occur. I've also upgraded from 12.5 to 13.3.
I no longer have a production setup that uses index built in this way:
CREATE INDEX entity_attribute_name_ids_gin ON public.entity USING gin
(attribute_name_ids public.gin__int_ops);
2 weeks ago i've moved to
CREATE INDEX entity_attribute_name_ids_gin ON public.entity USING gin
(attribute_name_ids);
And have not seen the problem manifest again.
Nevertheless - I have 2 file-level dumps of databases where we caught
the inconsistency and would like to help with diagnosing the problem.
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 21:47 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 20:14 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-25 20:27 ` Peter Geoghegan <pg@bowt.ie>
2021-07-25 20:47 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Peter Geoghegan @ 2021-07-25 20:27 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Alexander Korotkov <aekorotkov@gmail.com>; Tom Lane <tgl@sss.pgh.pa.us>
Just to make sure: are you using any kind of storage or other
virtualization, or a SAN? And what is your approach to backups?
Peter Geoghegan
(Sent from my phone)
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 21:47 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 20:14 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-25 20:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
@ 2021-07-25 20:47 ` Pawel Kudzia <kudzia@gmail.com>
0 siblings, 0 replies; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-25 20:47 UTC (permalink / raw)
To: Peter Geoghegan <pg@bowt.ie>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Alexander Korotkov <aekorotkov@gmail.com>; Tom Lane <tgl@sss.pgh.pa.us>
On Sun, Jul 25, 2021 at 10:27 PM Peter Geoghegan <pg@bowt.ie> wrote:
>
> Just to make sure: are you using any kind of storage or other virtualization, or a SAN? And what is your approach to backups?
>
> Peter Geoghegan
> (Sent from my phone)
It's locally attached storage:
2x NVMe installed in the server
on them mdadm RAID1
on that LUKS full disk encryption
on that ext4
please note that exactly the same storage / partition holds also MySQL
and Sphinxsearch databases - all those run at the same server, under
different users. all of them [ PG, MySQL, Sphinx ] are under heavy
read traffic and update traffic comparable to one described above for
postgresql - there are no consistency issues in Sphinx, MySQL
databases.
postgresql backups are done with pg_dumpall every 24h, we also use
streaming replication so servers where inconsistencies were found are
also masters for 5 replicas.
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-25 19:08 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 20:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-10-14 01:26 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
1 sibling, 2 replies; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-25 19:08 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 23/07/2021 18:04, Pawel Kudzia wrote:
> Thanks a lot for your patience and multiple patches that you've
> provided. Please pardon my ignorance - I don't have low-level
> understanding of how the query is being executed - but are you sure
> that index is missing entries and not the other way around - that it
> has too many entries?
To be precise, the index has an extra entry for row (4002784,1) with key
1373, and it's missing the entry with key 38048120. And for row
(4002869,14), it has an extra row for key 1373, and it's missing the
entry for key 95333744.
> To recap - SELECT, answered based on the GIN, reports rows that
> actually do not match the criteria provided in WHERE. Just lowering
> work_mem makes the problem go away, whith GIN still being used.
The reason that lowering work_mem hides the problem is that GIN collects
all the matches in a so called TID bitmap, and if the bitmap grows too
large compared to work_mem, it becomes lossy to save memory. When it's
lossy, it only stores the heap block numbers of the matches. For a
regular, non-lossy, match, the Bitmap Heap Scan just returns the row
that the index says is a match. For the lossy matches, the Bitmap Heap
Scan node needs to check every row on the page to see which ones
actually match. This re-checking hides the problem that some of the
matches that the index reported were not real.
Note that you are also getting incorrect results with missing row for
other queries. You can try it with e.g.:
-- Using the index
set enable_seqscan=off;
set enable_bitmapscan=on;
SELECT count(*) FROM entity WHERE attribute_name_ids && '{95333744}';
SELECT count(*) FROM entity WHERE attribute_name_ids && '{38048120}';
-- Without index
set enable_seqscan=on;
set enable_bitmapscan=off;
SELECT count(*) FROM entity WHERE attribute_name_ids && '{95333744}';
SELECT count(*) FROM entity WHERE attribute_name_ids && '{38048120}';
I'll work on a patch to add more sanity checks to the GIN code when it
traverses the tree, to catch the case that it accidentally steps on a
wrong kind of a page (I'm pretty busy next week, so might not get to
that until the week after though). I don't think that will help here,
but who knows, and at least we can rule out some kinds of bugs.
Alexander, can you finish the fixes to the ternary logic? That doesn't
explain this corruption either, but we should fix it anyway.
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-25 19:08 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-25 20:27 ` Pawel Kudzia <kudzia@gmail.com>
1 sibling, 0 replies; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-25 20:27 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Sun, Jul 25, 2021 at 9:08 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>
> On 23/07/2021 18:04, Pawel Kudzia wrote:
> > Thanks a lot for your patience and multiple patches that you've
> > provided. Please pardon my ignorance - I don't have low-level
> > understanding of how the query is being executed - but are you sure
> > that index is missing entries and not the other way around - that it
> > has too many entries?
>
> To be precise, the index has an extra entry for row (4002784,1) with key
> 1373, and it's missing the entry with key 38048120. And for row
> (4002869,14), it has an extra row for key 1373, and it's missing the
> entry for key 95333744.
>
> > To recap - SELECT, answered based on the GIN, reports rows that
> > actually do not match the criteria provided in WHERE. Just lowering
> > work_mem makes the problem go away, whith GIN still being used.
>
> The reason that lowering work_mem hides the problem is that GIN collects
> all the matches in a so called TID bitmap, and if the bitmap grows too
> large compared to work_mem, it becomes lossy to save memory. When it's
> lossy, it only stores the heap block numbers of the matches. For a
> regular, non-lossy, match, the Bitmap Heap Scan just returns the row
> that the index says is a match. For the lossy matches, the Bitmap Heap
> Scan node needs to check every row on the page to see which ones
> actually match. This re-checking hides the problem that some of the
> matches that the index reported were not real.
Thank you for the explanation!
>
> Note that you are also getting incorrect results with missing row for
> other queries. You can try it with e.g.:
>
> -- Using the index
> set enable_seqscan=off;
> set enable_bitmapscan=on;
> SELECT count(*) FROM entity WHERE attribute_name_ids && '{95333744}';
> SELECT count(*) FROM entity WHERE attribute_name_ids && '{38048120}';
>
> -- Without index
> set enable_seqscan=on;
> set enable_bitmapscan=off;
> SELECT count(*) FROM entity WHERE attribute_name_ids && '{95333744}';
> SELECT count(*) FROM entity WHERE attribute_name_ids && '{38048120}';
>
>
Actually - both give identical results - count(*) = 0.
I think you actually wanted me to run those:
data=# set enable_seqscan=off;
SET
data=# set enable_bitmapscan=on;
SET
data=# SELECT count(*) FROM entity WHERE attribute_name_ids && '{1737}';
count
-------
79565
(1 row)
data=# set enable_seqscan=on;
SET
data=# set enable_bitmapscan=off;
SET
data=# SELECT count(*) FROM entity WHERE attribute_name_ids && '{1737}';
count
-------
79560
(1 row)
Results indeed differ.
> I'll work on a patch to add more sanity checks to the GIN code when it
> traverses the tree, to catch the case that it accidentally steps on a
> wrong kind of a page (I'm pretty busy next week, so might not get to
> that until the week after though). I don't think that will help here,
> but who knows, and at least we can rule out some kinds of bugs.
> Alexander, can you finish the fixes to the ternary logic? That doesn't
> explain this corruption either, but we should fix it anyway.
>
Thanks a lot! I'm happy to test.
Greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 07:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-25 19:08 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-10-14 01:26 ` Peter Geoghegan <pg@bowt.ie>
1 sibling, 0 replies; 41+ messages in thread
From: Peter Geoghegan @ 2021-10-14 01:26 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Pawel Kudzia <kudzia@gmail.com>; Alexander Korotkov <aekorotkov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Sun, Jul 25, 2021 at 12:08 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> I'll work on a patch to add more sanity checks to the GIN code when it
> traverses the tree, to catch the case that it accidentally steps on a
> wrong kind of a page (I'm pretty busy next week, so might not get to
> that until the week after though). I don't think that will help here,
> but who knows, and at least we can rule out some kinds of bugs.
I just noticed that among call sites to ginInsertCleanup() located in
ginvacuum.c, only one caller specifies fill_fsm=true: The call made
when an autoanalyze (i.e. av worker that just does an ANALYZE) is run.
In other words, a call through the special analyze_only path [1].
Note, in particular, that a plain VACUUM, or a plain VACUUM ANALYZE
will always specify fill_fsm=false, regardless of any of the details.
This seems totally contradictory to me.
(***Thinks some more***)
Actually, that's not quite right -- it's not contradictory once you
realize that fill_fsm=true is an extra special path, originally
designed just for the analyze_only path. That's easy to see once you
look at commit dc943ad952 from 2015. Its specific goal was to allow
this special analyze_only path to recycle pages. We need fill_fsm=true
because the analyze_only path won't scan the whole index again at the
end of ginvacuumcleanup(). (Actually, why even scan it in the similar
cleanup-only VACUUM case? Ugh, that's not worth getting into now.)
In summary: Although I always suspected the fill_fsm=true ShiftList()
path here, it's even easier to suspect it now. Because I see now that
it hardly ever gets used inside autovacuum worker processes, though of
course it is possible. It's probably a matter of luck as to whether
you hit the analyze_only + fill_fsm=true ShiftList() path. That might
well have contributed to our difficulty in recreating the bugs here.
This is such a mess. I'm not sure that this insight will be news to
you, Heikki. Perhaps I'm just venting about the confused state of the
code here, following a recent unpleasant reminder (again, see [1]).
[1] https://postgr.es/m/CAH2-WzkjrK556enVtFLmyXEdw91xGuwiyZVep2kp5yQT_-3JDg@mail.gmail.com
--
Peter Geoghegan
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-06-25 20:48 ` Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
1 sibling, 1 reply; 41+ messages in thread
From: Alexander Korotkov @ 2021-06-25 20:48 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
(On Thu, Jun 24, 2021 at 3:59 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> On 17/06/2021 22:49, Tom Lane wrote:
> > I wrote:
> >> Pawel Kudzia <kudzia@gmail.com> writes:
> >>> with help from IRC we've found that decreasing work_mem from 1MB to 256kB
> >>> or less makes the problem go away:
> >
> >> Hmm. So that suggests that the index itself is *not* corrupt,
> >> but the problem is associated with a bug in the indexscan
> >> algorithms.
> >
> > After staring at the code I think there is at least one bug, and
> > possibly two, in shimTriConsistentFn. That's likely to be implicated
> > here because intarray's GIN opclass only provides a bool consistent
> > function. I'm not very clear on the circumstances that lead to the scan
> > code inventing GIN_MAYBE inputs, so I haven't been able to construct a
> > test case.
> >
> > The definite bug is triggered because intarray relies on the API
> > specification that says that if the search mode is
> > GIN_SEARCH_MODE_DEFAULT, then the consistentFn will only be called
> > when there's at least one TRUE key:
> >
> > case RTOverlapStrategyNumber:
> > /* result is not lossy */
> > *recheck = false;
> > /* at least one element in check[] is true, so result = true */
> > res = true;
> > break;
> >
> > shimTriConsistentFn ignores this and calls it on all-FALSE inputs,
> > for which it'll incorrectly get a TRUE result, as it will also for
> > all the following checks. The upshot is that shimTriConsistentFn
> > will convert any case with a MAYBE input to a hard TRUE result,
> > with no recheck requirement. This'd easily explain the reported
> > misbehavior.
>
> That's subtle. The documentation says:
>
> > If <literal>*searchMode</literal> is set to
> > <literal>GIN_SEARCH_MODE_DEFAULT</literal> (which is the value it is
> > initialized to before call), only items that match at least one of
> > the returned keys are considered candidate matches.
>
> I guess you can read that as "consistentFn will only be called when
> there is at least one matching item", but that didn't occur to me when I
> read that at first. But I agree we need to fix shimTriConsistentFn to
> respect that.
>
> > The other thing that I'm unsure about, because the code is horribly
> > underdocumented, is that it's not very clear whether
> > shimTriConsistentFn is accurately converting between the bool and
> > the tristate APIs. That's because it's not very clear what the
> > tristate API actually *is*. In particular, is the end state of
> > key->recheckCurItem meaningful in the tristate case? If it's not,
> > then the short-circuit case for no MAYBE inputs is broken, because
> > it'll return TRUE when the bool consistentFn is trying to tell us
> > to recheck. But if it is meaningful, then the multiway case is broken,
> > because it will return the recheckCurItem result set by the last call to
> > the bool consistentfn; which might be false even though other calls said
> > true. (So in that case I think we'd need "key->recheckCurItem = recheck"
> > at the end.) I also wonder how any of that works correctly for real
> > triconsistent functions, which don't have access to the recheckCurItem
> > flag.
> >
> > Anyway, I'm punting this to the code authors. I'd like to see
> > some comments clarifying what the API really is, not just a
> > quick-n-dirty code fix.
>
> I've been trying to create a test case for this, but no luck so far. I
> cannot find a codepath that would hit these bugs with the kind of query
> that Pawel used. The search condition is very simple: "column &&
> '{constant}'", with only one key and one constant to search for. There
> are three calls to triConsistentFn:
>
> 1. In startScanKey, but that's only reached if (key->nentries > 1), so
> not reachable with Pawel's query.
>
> 2. In keyGetItem, when haveLossyEntry==true. But AFAICS, haveLossyEntry
> is never true with Pawel's query. That would require curItem to be a
> lossy pointer, and that in turn can only happen when matchBitmap is
> used, and that's only used with partial match queries and with queries
> that need a full-index scan.
>
> 3. The second call in keyGetItem is reached, but it is only passed
> GIN_MAYBE when curItem is lossy. Which isn't possible with this query,
> see point 2.
>
> AFAICS the recheckCurItem bug should also not cause wrong results with
> that query. I must be missing something.
>
> I could probably construct a test case with a different query, one
> involving multiple elements in the search key, but I'd like to have a
> solid explanation for the original report.
+1,
I see query provided by Pawel is too simple. Bugs, which Tom digged
in shimTriConsistentFn() don't seem to explain the wrong query results
provided by Pawel.
> Pawel, is this a production system, or would it be possible for you to
> build from sources with a patch with some extra debugging output?
Do you think it also worth checking whether bug persists when set
fastupdate = off. Then we could localize whether bug is related to
pending lists.
------
Regards,
Alexander Korotkov
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
@ 2021-07-15 10:56 ` Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 13:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-16 23:40 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
0 siblings, 2 replies; 41+ messages in thread
From: Alexander Korotkov @ 2021-07-15 10:56 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Fri, Jun 25, 2021 at 11:48 PM Alexander Korotkov
<aekorotkov@gmail.com> wrote:
> Do you think it also worth checking whether bug persists when set
> fastupdate = off. Then we could localize whether bug is related to
> pending lists.
I still think this is worth checking. Despite the pending list wasn't
involved in the index scan with wrong results, the bug could be
related to insertion to the pending list. Or it could be related to
moving entries from the pending list to the posting list/tree.
------
Regards,
Alexander Korotkov
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
@ 2021-07-15 13:27 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-15 14:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
1 sibling, 1 reply; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-15 13:27 UTC (permalink / raw)
To: Alexander Korotkov <aekorotkov@gmail.com>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
> On Fri, Jun 25, 2021 at 11:48 PM Alexander Korotkov
> <aekorotkov@gmail.com> wrote:
> > Do you think it also worth checking whether bug persists when set
> > fastupdate = off. Then we could localize whether bug is related to
> > pending lists.
>
> I still think this is worth checking. Despite the pending list wasn't
> involved in the index scan with wrong results, the bug could be
> related to insertion to the pending list. Or it could be related to
> moving entries from the pending list to the posting list/tree.
>
regarding fastupdate - i'd like to clarify. do i understand correctly
that this parameter affects what happens when rows are
inserted/updated/deleted?
if yes - we no longer have such workload on the production and we
cannot anymore and i was never able to find reproducible scenario.
the production environment was moved away from index built "USING gin
(attribute_name_ids public.gin__int_ops)" to index "USING gin
(attribute_name_ids)".
the only thing i have right two file-level backups of postgresql data
directory on which i know that SELECTs return rows that actually don't
meet provided criteria.
is there any point in testing fastupdate = off on those two snapshots?
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 13:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
@ 2021-07-15 14:24 ` Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 14:28 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
0 siblings, 1 reply; 41+ messages in thread
From: Alexander Korotkov @ 2021-07-15 14:24 UTC (permalink / raw)
To: Pawel Kudzia <kudzia@gmail.com>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Thu, Jul 15, 2021 at 4:27 PM Pawel Kudzia <kudzia@gmail.com> wrote:
> > On Fri, Jun 25, 2021 at 11:48 PM Alexander Korotkov
> > <aekorotkov@gmail.com> wrote:
> > > Do you think it also worth checking whether bug persists when set
> > > fastupdate = off. Then we could localize whether bug is related to
> > > pending lists.
> >
> > I still think this is worth checking. Despite the pending list wasn't
> > involved in the index scan with wrong results, the bug could be
> > related to insertion to the pending list. Or it could be related to
> > moving entries from the pending list to the posting list/tree.
> >
>
> regarding fastupdate - i'd like to clarify. do i understand correctly
> that this parameter affects what happens when rows are
> inserted/updated/deleted?
Yes, that's it.
> if yes - we no longer have such workload on the production and we
> cannot anymore and i was never able to find reproducible scenario.
> the production environment was moved away from index built "USING gin
> (attribute_name_ids public.gin__int_ops)" to index "USING gin
> (attribute_name_ids)".
Do I understand correctly that after the production environment moved
away from the usage of contrib/intarray opclass to builtin opclass,
the error has gone?
> the only thing i have right two file-level backups of postgresql data
> directory on which i know that SELECTs return rows that actually don't
> meet provided criteria.
>
> is there any point in testing fastupdate = off on those two snapshots?
OK, I see. No point in trying fastupdate = off unless we can try to
reproduce the index corruption.
------
Regards,
Alexander Korotkov
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 13:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Pawel Kudzia <kudzia@gmail.com>
2021-07-15 14:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
@ 2021-07-15 14:28 ` Pawel Kudzia <kudzia@gmail.com>
0 siblings, 0 replies; 41+ messages in thread
From: Pawel Kudzia @ 2021-07-15 14:28 UTC (permalink / raw)
To: Alexander Korotkov <aekorotkov@gmail.com>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
>
>
> On Thu, Jul 15, 2021 at 4:27 PM Pawel Kudzia <kudzia@gmail.com> wrote:
> > > On Fri, Jun 25, 2021 at 11:48 PM Alexander Korotkov
> > > <aekorotkov@gmail.com> wrote:
> > > > Do you think it also worth checking whether bug persists when set
> > > > fastupdate = off. Then we could localize whether bug is related to
> > > > pending lists.
> > >
> > > I still think this is worth checking. Despite the pending list wasn't
> > > involved in the index scan with wrong results, the bug could be
> > > related to insertion to the pending list. Or it could be related to
> > > moving entries from the pending list to the posting list/tree.
> > >
> >
> > regarding fastupdate - i'd like to clarify. do i understand correctly
> > that this parameter affects what happens when rows are
> > inserted/updated/deleted?
>
> Yes, that's it.
>
> > if yes - we no longer have such workload on the production and we
> > cannot anymore and i was never able to find reproducible scenario.
> > the production environment was moved away from index built "USING gin
> > (attribute_name_ids public.gin__int_ops)" to index "USING gin
> > (attribute_name_ids)".
>
> Do I understand correctly that after the production environment moved
> away from the usage of contrib/intarray opclass to builtin opclass,
> the error has gone?
>
it's a bit too early to be confident - i'd give it at least 2-3 more weeks
before stating that the problem was solved.
in the past, when using gin__int_ops, we had periods of few consecutive
days when we did not catch any inconsistent reposnes.
> > the only thing i have right two file-level backups of postgresql data
> > directory on which i know that SELECTs return rows that actually don't
> > meet provided criteria.
> >
> > is there any point in testing fastupdate = off on those two snapshots?
>
> OK, I see. No point in trying fastupdate = off unless we can try to
> reproduce the index corruption.
>
thx for the clarification!
i'm happy to help with running more diagnostics on the database dumps that
i've saved, where very specific SELECTs return rows that don't match
provided criteria.
greetings!
--
regards,
Pawel Kudzia
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
@ 2021-07-16 23:40 ` Peter Geoghegan <pg@bowt.ie>
2021-07-17 00:30 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
1 sibling, 1 reply; 41+ messages in thread
From: Peter Geoghegan @ 2021-07-16 23:40 UTC (permalink / raw)
To: Alexander Korotkov <aekorotkov@gmail.com>; +Cc: Heikki Linnakangas <hlinnaka@iki.fi>; Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Thu, Jul 15, 2021 at 3:56 AM Alexander Korotkov <aekorotkov@gmail.com> wrote:
> I still think this is worth checking. Despite the pending list wasn't
> involved in the index scan with wrong results, the bug could be
> related to insertion to the pending list. Or it could be related to
> moving entries from the pending list to the posting list/tree.
If I had to guess I'd say that the chances of the pending list being
involved are high.
shiftList() deletes pages in the pending list -- this is called from
ginInsertCleanup(). But shiftList() doesn't call GinPageSetDeleteXid()
to set an XID that represents when the page is safe to recycle, which
is what ginDeletePage() always does. Why is that okay?
Note that we usually use read/share buffer locks when lock-coupling
inside ginInsertCleanup() -- so AFAICT we won't block-out concurrent
readers with a link that's about to go stale due to recycling of the
page. This looks unsafe. Of course it's very hard to tell what might
be going on, since none of this seems to be explained anywhere.
Even ginDeletePage() didn't do the right thing with XIDs until bugfix
commit 52ac6cd2d0. That commit didn't touch any pending list code --
it should of at least explained why ginInsertCleanup()/shiftList()
don't need to use the GinPageSetDeleteXid() stuff.
--
Peter Geoghegan
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-16 23:40 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
@ 2021-07-17 00:30 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 01:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-17 00:30 UTC (permalink / raw)
To: Peter Geoghegan <pg@bowt.ie>; Alexander Korotkov <aekorotkov@gmail.com>; +Cc: Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 17/07/2021 02:40, Peter Geoghegan wrote:
> On Thu, Jul 15, 2021 at 3:56 AM Alexander Korotkov <aekorotkov@gmail.com> wrote:
>> I still think this is worth checking. Despite the pending list wasn't
>> involved in the index scan with wrong results, the bug could be
>> related to insertion to the pending list. Or it could be related to
>> moving entries from the pending list to the posting list/tree.
>
> If I had to guess I'd say that the chances of the pending list being
> involved are high.
>
> shiftList() deletes pages in the pending list -- this is called from
> ginInsertCleanup(). But shiftList() doesn't call GinPageSetDeleteXid()
> to set an XID that represents when the page is safe to recycle, which
> is what ginDeletePage() always does. Why is that okay?
>
> Note that we usually use read/share buffer locks when lock-coupling
> inside ginInsertCleanup() -- so AFAICT we won't block-out concurrent
> readers with a link that's about to go stale due to recycling of the
> page. This looks unsafe. Of course it's very hard to tell what might
> be going on, since none of this seems to be explained anywhere.
>
> Even ginDeletePage() didn't do the right thing with XIDs until bugfix
> commit 52ac6cd2d0. That commit didn't touch any pending list code --
> it should of at least explained why ginInsertCleanup()/shiftList()
> don't need to use the GinPageSetDeleteXid() stuff.
Hmm, seems we should fix that. But could a prematurely recycled deleted
page cause permanent corruption?
Here's what I've found out so far, looking at the traces Pawel sent:
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 0 (ginutil.c:636 ginGetStats)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 0 (ginget.c:1866 scanPendingInsert)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 383295 (ginget.c:1894 scanPendingInsert)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 383298 (ginget.c:1518 scanGetCandidate)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 2 (ginget.c:1518 scanGetCandidate)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 3 (ginget.c:1518 scanGetCandidate)
> [few hundred calls from scanGetCandidate omitted]
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 200586 (ginget.c:1518 scanGetCandidate)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 200854 (ginget.c:1518 scanGetCandidate)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 1 (ginbtree.c:89 ginFindLeafPage)
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 1452 (ginbtree.c:89 ginFindLeafPage)
> 2021-07-16 07:01:19 UTC LOG: GINBUG: startScanKey called: excludeOnly 0 nentries 1
> 2021-07-16 07:01:19 UTC LOG: GINBUG: called triConsistentFn(1): 1 0
> 2021-07-16 07:01:19 UTC LOG: GINBUG: called triConsistentFn(1): 1 0
> 2021-07-16 07:01:19 UTC LOG: GINBUG: called triConsistentFn(1): 1 0
> ...
So, it begins by reading the metadata page, and then it scans the
pending list. There are a few hundred pages in the pending list, but no
matches are found there.
Then, it reads the root page at blk 1. And then, it reads page 1452.
I used pg_filedump on the root page (blk 1):
> Block 1 ********************************************************
> <Header> -----
> Block Offset: 0x00002000 Offsets: Lower 1376 (0x0560)
> Block: Size 8192 Version 4 Upper 2776 (0x0ad8)
> LSN: logid 410 recoff 0x04c6b6c0 Special 8184 (0x1ff8)
> Items: 338 Free Space: 1400
> Checksum: 0xde29 Prune XID: 0x00000000 Flags: 0x0000 ()
> Length (including item array): 1376
>
> <Data> -----
> Item 1 -- Length: 16 Offset: 7736 (0x1e38) Flags: NORMAL
> Item 2 -- Length: 16 Offset: 8168 (0x1fe8) Flags: NORMAL
> Item 3 -- Length: 16 Offset: 7800 (0x1e78) Flags: NORMAL
> ...
> Item 337 -- Length: 16 Offset: 7032 (0x1b78) Flags: NORMAL
> Item 338 -- Length: 16 Offset: 8152 (0x1fd8) Flags: NORMAL
>
> <Special Section> -----
> GIN Index Section:
> Flags: 0x00000000 () Maxoff: 0
> Blocks: RightLink (-1)
It has no Flags set, which means that it is an internal entry tree page.
The items on an internal entry tree page should point to other entry
tree pages. Now let's take a look at the next page that it read, blk 1452:
> Block 1452 ********************************************************
> <Header> -----
> Block Offset: 0x00b58000 Offsets: Lower 562 (0x0232)
> Block: Size 8192 Version 4 Upper 8184 (0x1ff8)
> LSN: logid 471 recoff 0xf0cf8a68 Special 8184 (0x1ff8)
> Items: 134 Free Space: 7622
> Checksum: 0x1628 Prune XID: 0x00000000 Flags: 0x0000 ()
> Length (including item array): 560
>
> <Data> -----
> Item 1 -- Length: 0 Offset: 0 (0x0000) Flags: UNUSED
> Item 2 -- Length: 0 Offset: 0 (0x0000) Flags: UNUSED
> Item 3 -- Length: 7780 Offset: 0 (0x0000) Flags: UNUSED
> Item 4 -- Length: 5990 Offset: 4 (0x0004) Flags: UNUSED
> Item 5 -- Length: 0 Offset: 6 (0x0006) Flags: UNUSED
> Item 6 -- Length: 2 Offset: 15559 (0x3cc7) Flags: UNUSED
> Error: Item contents extend beyond block.
> BlockSize<8192> Bytes Read<8192> Item Start<15561>.
> Item 7 -- Length: 3 Offset: 15372 (0x3c0c) Flags: REDIRECT
> ...
> Item 133 -- Length: 20913 Offset: 3 (0x0003) Flags: UNUSED
> Error: Item contents extend beyond block.
> BlockSize<8192> Bytes Read<8192> Item Start<20916>.
> Item 134 -- Length: 0 Offset: 0 (0x0000) Flags: UNUSED
>
> <Special Section> -----
> GIN Index Section:
> Flags: 0x00000001 (DATA) Maxoff: 53
> Blocks: RightLink (-1)
On this page, the DATA flag is set, so it is an internal *posting* tree
page.
That's weird: the scan walked straight from an internal entry tree page
(root, at blk 1) into an internal posting tree page (blk 1452). That
doesn't make sense to me.
The next ReadBuffer call is this:
> 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 15559 (ginbtree.c:183 ginStepRight)
Where did block 15559 come from? How come we're stepping right to it?
It's not the right sibling of the previously accessed page, 1452. In
fact, 15559 is a leaf posting tree page. I don't understand how that
sequence of page reads could happen.
After that, the log shows that it follows the right-links from block
15559 onward. The incorrectly returned entries are on posting tree page
255179. The scan reaches that page by following that chain of right-links.
I'm going to continue investigating this on Monday. I'll take a closer
look at the index entries on those blocks to see if I can make sense of it.
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-16 23:40 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-17 00:30 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-17 01:56 ` Peter Geoghegan <pg@bowt.ie>
2021-07-17 21:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 41+ messages in thread
From: Peter Geoghegan @ 2021-07-17 01:56 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Fri, Jul 16, 2021 at 5:30 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> Hmm, seems we should fix that. But could a prematurely recycled deleted
> page cause permanent corruption?
If scans can find a page that is wholly unrelated to the expected page
(and possibly even in the wrong high level page category), then it's
really hard to predict what might happen. This could lead to real
chaos. ginInsertCleanup() makes no attempt to perform basic validation
of its assumptions about what kind of page this is, except for some
assertions. We should have something like a "can't happen" error on
!GinPageIsList() inside ginInsertCleanup() -- if we had that already
then I might be able to reason about this problem. It wouldn't hurt to
have similar checks in other code that deals with posting trees and
entry trees, too.
ginInsertCleanup() is tolerant of all kinds of things. It's not just
the lack of page-level sanity checks. It's also the basic approach to
crash safety, which relies on the fact that GIN only does lossy index
scans. My guess is that there could be lots of problems without it
being obvious to users. Things really went downhill in
ginInsertCleanup() starting in commit e956808328.
> On this page, the DATA flag is set, so it is an internal *posting* tree
> page.
>
> That's weird: the scan walked straight from an internal entry tree page
> (root, at blk 1) into an internal posting tree page (blk 1452). That
> doesn't make sense to me.
I agree that the internal entry tree page (root, at blk 1) looks sane,
from what I've seen. The tuple sizes are plausible -- 16 byte index
tuples aren't possible on an entry tree leaf page. Nor in a pending
list page.
Anyway, this is roughly the kind of bug I had in mind. It's possible
that the underlying problem doesn't actually involve
ginInsertCleanup() -- as I said we have seen similar issues elsewhere
(one such issue was fixed in commit 52ac6cd2d0). But as Alexander
pointed out, that doesn't mean much. It's possible that this problem
is 1 or 2 problems removed from the original problem, which really did
start in ginInsertCleanup() -- who knows? Why shouldn't corruption
lead to more corruption, given that we don't do much basic page level
validation? We do at least sanitize within ginStepRight(), but we need
to be more consistent about it.
> The next ReadBuffer call is this:
>
> > 2021-07-16 07:01:19 UTC LOG: ReadBuffer 1663/16390/16526 read gin blk 15559 (ginbtree.c:183 ginStepRight)
>
> Where did block 15559 come from? How come we're stepping right to it?
> It's not the right sibling of the previously accessed page, 1452. In
> fact, 15559 is a leaf posting tree page. I don't understand how that
> sequence of page reads could happen.
Maybe take a look at Block 1452 using pg_hexedit? pg_hexedit is
designed to do well at interpreting quasi-corrupt data (or at least
allowing the user to do so). We see from your pg_filedump output that
the tuple contents for the page are totally wild. We should not trust
the reported right sibling page, given everything else -- is that
really what Postgres thinks the right sibling is? I mean, clearly it
doesn't.
I think it's possible that pg_filedump is interpreting it in a way
that is kind of wrong. If you saw the same page (1452) in pg_hexedit
you might spot a pattern that pg_filedump output will never reveal. At
least looking at the raw bytes might give you some idea.
--
Peter Geoghegan
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-16 23:40 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-17 00:30 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 01:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
@ 2021-07-17 21:27 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 23:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
0 siblings, 1 reply; 41+ messages in thread
From: Heikki Linnakangas @ 2021-07-17 21:27 UTC (permalink / raw)
To: Peter Geoghegan <pg@bowt.ie>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On 17/07/2021 04:56, Peter Geoghegan wrote:
> On Fri, Jul 16, 2021 at 5:30 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
>> Hmm, seems we should fix that. But could a prematurely recycled deleted
>> page cause permanent corruption?
>
> If scans can find a page that is wholly unrelated to the expected page
> (and possibly even in the wrong high level page category), then it's
> really hard to predict what might happen. This could lead to real
> chaos.
Right. Looking at the code, I don't think that can happen. The code that
deals with the pending list uses lock coupling, so it should never
follow a pointer to a page that was concurrently deleted. Might
something funny happen if a pending list page is deleted and immediately
reused as another kind of page? I don't see a problem with that. And a
gin btree page won't be reused prematurely as a pending list page,
because ginNewBuffer() checks GinPageIsRecyclable(), even if the page is
being reused as a pending list page.
> ginInsertCleanup() makes no attempt to perform basic validation
> of its assumptions about what kind of page this is, except for some
> assertions. We should have something like a "can't happen" error on
> !GinPageIsList() inside ginInsertCleanup() -- if we had that already
> then I might be able to reason about this problem. It wouldn't hurt to
> have similar checks in other code that deals with posting trees and
> entry trees, too.
+1
While playing with the trace Pawel sent, I loaded some of the index
pages into a local instance so that I could step through the code with
gdb. I filled the rest of the pages with zeros. I managed to get the gin
btree descend code into an infinite loop with that. When it followed a
pointer to an entry leaf page, but that entry leaf page was substituted
with zeros, it interpreted the all-zeros page as a page with a
right-link to block 0. It then stepped right to read block 0 - which is
the metapage! - and incorrectly interpreted it as an internal page.
Amazingly, it managed to perform the binary search on it as if it
contained index tuples, and came up wth an another block number, which I
had also replaced with all-zeros.
Long story short, we should sprinkle a lot more sanity checks to the
functions in ginbtree.c. It should check that the page is of expected
kind; no stepping from internal entry page to posting tree page. And
seeing a pointer to block 0 at any step should be an error.
But this was just an artifact of the missing pages my test. It doesn't
explain the original problem.
> ginInsertCleanup() is tolerant of all kinds of things. It's not just
> the lack of page-level sanity checks. It's also the basic approach to
> crash safety, which relies on the fact that GIN only does lossy index
> scans. My guess is that there could be lots of problems without it
> being obvious to users. Things really went downhill in
> ginInsertCleanup() starting in commit e956808328.
Yeah, I wouldn't be surprised if this turns out to be a bug in pending
list cleanup. But I haven't been able to come up with a concrete
sequence of steps that would cause it.
- Heikki
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-16 23:40 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-17 00:30 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 01:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-17 21:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
@ 2021-07-17 23:25 ` Peter Geoghegan <pg@bowt.ie>
2021-07-18 01:24 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
0 siblings, 1 reply; 41+ messages in thread
From: Peter Geoghegan @ 2021-07-17 23:25 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Sat, Jul 17, 2021 at 2:27 PM Heikki Linnakangas <hlinnaka@iki.fi> wrote:
> Right. Looking at the code, I don't think that can happen. The code that
> deals with the pending list uses lock coupling, so it should never
> follow a pointer to a page that was concurrently deleted. Might
> something funny happen if a pending list page is deleted and immediately
> reused as another kind of page? I don't see a problem with that.
I don't immediately see a problem either, but that hardly means much
-- I can't honestly claim that I understand the code here.
Why does the code in ginInsertCleanup() use lock coupling? It's
probably true that if you don't couple pending list pages then the
tests would break in an obvious way, but that tells us nothing about
the design itself. It was probably self-evident what was going on in
earlier versions of the code, back when it could only run in VACUUM
anyway, when it didn't eagerly recycle pending list pages, etc. But
it's far from obvious now that we have all that stuff too.
Let's say processPendingPage() finds a page that is fundamentally of
the wrong kind (i.e. not a pending page). Why shouldn't the result be
something scary (some kind of data corruption), that doesn't come with
an error or hard crash? I can see no reason. Small differences in the
format of the tuples seem unlikely to be caught anywhere, at least
offhand.
Another possible consequence of the lack of sanity checking is that
whole *groups* of sibling pages (say from a posting tree or the entry
tree) that look like they're a group from the pending list (but are
actually from some tree) could get corrupted, one by one. This could
happen as a secondary effect of the initial corruption, which might
have only affected one page at first. Why shouldn't ginInsertCleanup()
do that? Almost all GIN pages use "GinPageGetOpaque(page)->rightlink"
in one way or another. If this is what happened then there really is
no telling what you'll end up with. You may have a very hard time
zeroing in on the truly relevant corruption.
> And a
> gin btree page won't be reused prematurely as a pending list page,
> because ginNewBuffer() checks GinPageIsRecyclable(), even if the page is
> being reused as a pending list page.
It doesn't matter that ginNewBuffer() checks GinPageIsRecyclable(),
since the page header's pd_prune_xid field will be 0 for a pending
list page (same as other index AMs, though not the same as other GIN
code). Note that GinPageIsRecyclable() returns "true" (safe to
recycle) when it sees any "pd_prune_xid = 0" page, by design. Also, if
ginInsertCleanup() ever tries to process/delete a posting tree or
entry tree page, then it's still not going to set pd_prune_xid in the
first place (because it believes that they're pending list pages).
> While playing with the trace Pawel sent, I loaded some of the index
> pages into a local instance so that I could step through the code with
> gdb. I filled the rest of the pages with zeros. I managed to get the gin
> btree descend code into an infinite loop with that. When it followed a
> pointer to an entry leaf page, but that entry leaf page was substituted
> with zeros, it interpreted the all-zeros page as a page with a
> right-link to block 0. It then stepped right to read block 0 - which is
> the metapage! - and incorrectly interpreted it as an internal page.
> Amazingly, it managed to perform the binary search on it as if it
> contained index tuples, and came up wth an another block number, which I
> had also replaced with all-zeros.
That doesn't actually surprise me. I have deliberately corrupted a lot
of test data in all kinds of ways. I have some idea how broken things
can be internally without breaking in a very obvious way.
> Long story short, we should sprinkle a lot more sanity checks to the
> functions in ginbtree.c. It should check that the page is of expected
> kind; no stepping from internal entry page to posting tree page. And
> seeing a pointer to block 0 at any step should be an error.
Definitely.
> Yeah, I wouldn't be surprised if this turns out to be a bug in pending
> list cleanup. But I haven't been able to come up with a concrete
> sequence of steps that would cause it.
I also wouldn't be surprised if it was some unrelated issue, despite
everything. As broken as I think the code in ginInsertCleanup() is, it
has managed to be broken without anybody noticing for quite a while on
a few occasions already. So unfortunately all of my observations about
ginInsertCleanup() may in the end not help you to find the true
underlying bug.
--
Peter Geoghegan
^ permalink raw reply [nested|flat] 41+ messages in thread
* Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-25 20:48 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Alexander Korotkov <aekorotkov@gmail.com>
2021-07-16 23:40 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-17 00:30 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 01:56 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
2021-07-17 21:27 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 23:25 ` Re: IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Peter Geoghegan <pg@bowt.ie>
@ 2021-07-18 01:24 ` Peter Geoghegan <pg@bowt.ie>
0 siblings, 0 replies; 41+ messages in thread
From: Peter Geoghegan @ 2021-07-18 01:24 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Korotkov <aekorotkov@gmail.com>; Pawel Kudzia <kudzia@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Tom Lane <tgl@sss.pgh.pa.us>
On Sat, Jul 17, 2021 at 4:25 PM Peter Geoghegan <pg@bowt.ie> wrote:
> > And a
> > gin btree page won't be reused prematurely as a pending list page,
> > because ginNewBuffer() checks GinPageIsRecyclable(), even if the page is
> > being reused as a pending list page.
>
> It doesn't matter that ginNewBuffer() checks GinPageIsRecyclable(),
> since the page header's pd_prune_xid field will be 0 for a pending
> list page (same as other index AMs, though not the same as other GIN
> code). Note that GinPageIsRecyclable() returns "true" (safe to
> recycle) when it sees any "pd_prune_xid = 0" page, by design. Also, if
> ginInsertCleanup() ever tries to process/delete a posting tree or
> entry tree page, then it's still not going to set pd_prune_xid in the
> first place (because it believes that they're pending list pages).
To be clear, I'm not worried about premature reuse of some other page
as a pending list page -- that should be fine. I'm worried about
unsafe early reuse of pending list pages, where the new page image is
related to either a posting tree or the entry tree. I think that it's
possible that the whole locking protocol can't handle premature
recycling, because it wasn't really built with that in mind.
shiftList() will call RecordFreeIndexPage() for pages it deletes as of
commit e956808328 from 2015. I find the code hard to follow, but I
suspect that some place cannot handle it if a
marked-GIN_DELETED-by-shiftList() page gets concurrently recycled.
Distant code may need to still have the same right link (and even the
same page contents?) to handle everything.
For example, distant code like scanGetCandidate() from ginget.c
participates in buffer lock coupling of pending list pages, and so has
interactions with ginInsertCleanup() and its own lock coupling. But
scanGetCandidate() hasn't changed since 2009, and might well have been
missed by the numerous bug fixes that changed scanGetCandidate() code
following commit e956808328 from 2015. Nearby code in
scanPendingInsert() also hasn't been changed since 2009. But
ginInsertCleanup() *has* changed since that time, by quite a bit.
Starting with making shiftList() call RecordFreeIndexPage() for pages
it deletes. But other stuff too.
I might be mistaken in certain details, but the fact that it's so hard
to keep all the details straight concerns me.
--
Peter Geoghegan
^ permalink raw reply [nested|flat] 41+ messages in thread
1 further message in this thread omitted from this page (render size limit).
Use the per-message pages, or the t.mbox.gz byte stream, for the complete thread.
end of thread, other threads:[~2021-10-14 01:26 UTC | newest]
Thread overview: 41+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-06-24 12:59 IRe: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows Heikki Linnakangas <hlinnaka@iki.fi>
2021-06-24 13:32 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-05 13:36 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-11 18:42 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-12 17:24 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-13 22:25 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-13 23:02 ` Peter Geoghegan <pg@bowt.ie>
2021-07-14 14:37 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-15 07:04 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-15 09:38 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-15 18:49 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-16 07:06 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-17 20:51 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-18 08:27 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-20 11:55 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-20 12:22 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-20 15:34 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-21 10:49 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-22 07:25 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-22 09:07 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-22 09:08 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-23 13:46 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-23 15:04 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-23 21:47 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 20:14 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-25 20:27 ` Peter Geoghegan <pg@bowt.ie>
2021-07-25 20:47 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-25 19:08 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-25 20:27 ` Pawel Kudzia <kudzia@gmail.com>
2021-10-14 01:26 ` Peter Geoghegan <pg@bowt.ie>
2021-06-25 20:48 ` Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 10:56 ` Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 13:27 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-15 14:24 ` Alexander Korotkov <aekorotkov@gmail.com>
2021-07-15 14:28 ` Pawel Kudzia <kudzia@gmail.com>
2021-07-16 23:40 ` Peter Geoghegan <pg@bowt.ie>
2021-07-17 00:30 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 01:56 ` Peter Geoghegan <pg@bowt.ie>
2021-07-17 21:27 ` Heikki Linnakangas <hlinnaka@iki.fi>
2021-07-17 23:25 ` Peter Geoghegan <pg@bowt.ie>
2021-07-18 01:24 ` Peter Geoghegan <pg@bowt.ie>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox