Subject: Re: IRe: BUG #16792: silent corruption of GIN index resulting in
 SELECTs returning non-matching rows
To: Pawel Kudzia <kudzia@gmail.com>
Cc: Alexander Korotkov <aekorotkov@gmail.com>,
 pgsql-bugs@lists.postgresql.org, Tom Lane <tgl@sss.pgh.pa.us>
References: <16792-b1913b6b4e098331@postgresql.org>
 <CAJYBUS9AaEgFTXnZnAWir993-MOVLnXefQmyLd9erXewZhXiHA@mail.gmail.com>
 <CAJYBUS_5Z+9aHyNQ7wkTEkZF+c_RMn7hMjPkTGU0Uc7OHMU3sQ@mail.gmail.com>
 <CAJYBUS8p3aYh5ZWJHHk1QGnGkUepMHQMMm87kODoXOFS+VWVGQ@mail.gmail.com>
 <970432.1623938874@sss.pgh.pa.us> <1039976.1623959387@sss.pgh.pa.us>
 <efe09893-8e6d-9a34-8351-3ea3c6ab202a@iki.fi>
 <CAJYBUS9mmVvVPWKM4rNKJqaq85bQG0Rw20LvT05Fc3zOWt2MaQ@mail.gmail.com>
 <CAJYBUS84aSgCNhcusOJQfeWFy1V3U55AOmRUWcpd+SsF9_qp=A@mail.gmail.com>
From: Heikki Linnakangas <hlinnaka@iki.fi>
Message-ID: <920041ab-e975-afe3-77d0-934a7c50965d@iki.fi>
Date: Sun, 11 Jul 2021 21:42:54 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101
 Thunderbird/78.11.0
MIME-Version: 1.0
In-Reply-To: 
 <CAJYBUS84aSgCNhcusOJQfeWFy1V3U55AOmRUWcpd+SsF9_qp=A@mail.gmail.com>
Content-Type: multipart/mixed;
 boundary="------------CB528146EB784AB8B94992DB"
Content-Language: en-US
Archived-At: 
 <https://www.postgresql.org/message-id/920041ab-e975-afe3-77d0-934a7c50965d%40iki.fi>
Precedence: bulk

This is a multi-part message in MIME format.
--------------CB528146EB784AB8B94992DB
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit

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

--------------CB528146EB784AB8B94992DB
Content-Type: text/x-patch; charset=UTF-8;
 name="trace-gin-consistent-funcs-1.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="trace-gin-consistent-funcs-1.patch"

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;

--------------CB528146EB784AB8B94992DB--