Re: BUG #16792: silent corruption of GIN index resulting in SELECTs returning non-matching rows

On Sun, Dec 27, 2020 at 6:19 PM PG Bug reporting form
<noreply(at)postgresql(dot)org> wrote:
>
> The following bug has been logged on the website:
>
> Bug reference: 16792
> Logged by: pawel kudzia
> Email address: kudzia(at)gmail(dot)com
> PostgreSQL version: 11.10
> Operating system: Debian Buster x86_64
> Description:
>
> I'd like to ask for advice how to proceed with pin-pointing cause of the
> silent corruption of GIN index that I'm facing.
>
> Relevant part of the table structure:
>
> CREATE TABLE public.entity (
> entity_id bigint NOT NULL,
> attribute_value_ids integer[] NOT NULL,
> attribute_name_ids integer[] NOT NULL,
> [..]
> );
>
> ALTER TABLE ONLY public.entity ADD CONSTRAINT entity_pkey PRIMARY KEY
> (entity_id);
> CREATE INDEX entity_attribute_name_ids_gin ON public.entity USING gin
> (attribute_name_ids public.gin__int_ops);
> CREATE INDEX entity_attribute_value_ids_gin ON public.entity USING gin
> (attribute_value_ids public.gin__int_ops);
>
> How does the issue manifest?
>
> Queries which use GIN on integer[] column occasionally return too many rows,
> including ones that actually do not match criteria expressed in WHERE.
> Queries like below should never return any rows, yet - occasionally they do
> return some results:
>
> data=> SELECT entity_id FROM entity WHERE ( attribute_name_ids && '{4980}' )
> AND NOT ( (attribute_name_ids||0) && '{4980}') ;
> entity_id
> -----------
> 31213924
> 31195117
> 31209184
> (3 rows)
>
> Query plan:
> QUERY PLAN
> -------------------------------------------------------------------------------------------------
> Bitmap Heap Scan on entity (cost=50.39..3068.11 rows=26923 width=22)
> Recheck Cond: (attribute_name_ids && '{4980}'::integer[])
> Filter: (NOT ((attribute_name_ids || 0) && '{4980}'::integer[]))
> -> Bitmap Index Scan on entity_attribute_name_ids_gin (cost=0.00..50.39
> rows=27058 width=0)
> Index Cond: (attribute_name_ids && '{4980}'::integer[])
> (5 rows)
>
> The query was crafted intentionally to let PostgreSQL use GIN index
> entity_attribute_name_ids_gin [ left side of AND ] and then filter out rows
> that after inspection of their values do not actually match that criteria.
>
> What have I done so far?
>
> Originally the problem was discovered when running PostgreSQL 11.7 from
> Debian's repo. In the first step we've upgraded to PostgreSQL 11.9 also from
> Debian's repo and run:
>
> reindex (verbose) table entity; vacuum (verbose, full, analyze) entity;
>
> After few days of updates the problem returned.
>
> We've upgraded to PostgreSQL 11.10 from postgresql.org repository for Debian
> and reindexed / vacuumed again. After few weeks of updates problem returned
> again.
>
> Other information worth noting:
> * table in question has 38M rows and is the only table created after
> PostgreSQL installation
> * server in question is master of streaming replication; issue occurs also
> on the slave servers - this suggests corruption of the on-disk GIN index
> data
> * just rewriting rows falsely returned by select above - UPDATE entity SET
> attribute_name_ids ='{....}' WHERE entity_id=123 - fixes the issue
> * we've set up rudimentary consistency checks that allow to catch some of
> the corruptions within 1h of occurring - so far corruptions only happen to
> rows that have been updated since the previous check
> * server in question handles heavy read/write traffic
> * PostgreSQL in question runs in LXC container with Debian Buster running on
> top of Debian Buster running on top of bare-metal server
> * it's highly unlikely that hardware malfunction is to be blamed - the same
> physical server handles also few MySQL instances with hundreds of GB of data
> with heavy consistency checks cross checking content of MySQL with
> PostgreSQL, unpacking gzip'ed blobs stored in MySQL databases and
> de-serializing objects stored there. if there was a bit-rot / bit-flip in
> memory would that's not detected or fixed by ECC - high level consistency
> checks would pick it.
> * despite numerous attempts i cannot reproduce the issue in test
> environment, possibly due to much lower level of write traffic. it takes
> days to weeks to have it re-occur on the production server.
>
> Thank you in advance for your suggestions how to tackle this.
>
> best regards,
> Pawel
>

I'd like to provide more details from another occurrence of this issue:

psql (11.7 (Debian 11.7-0+deb10u1), server 11.9 (Debian 11.9-0+deb10u1))

Example where GIN is returning misleading information:

data=# SELECT entity_id,attribute_name_ids FROM entity WHERE (
attribute_name_ids && '{471}' ) AND NOT ( (attribute_name_ids||0) &&
'{471}') ;
entity_id | attribute_name_ids
-----------+------------------------------------------------------------------------------
197911914 | {2,3,4,6,7,8,9,10,13,17,35,48,66,71,3270,3273,3279,4377,4842,5379,5787,7416}
(1 row)

data=# EXPLAIN ANALYZE SELECT entity_id,attribute_name_ids FROM
entity WHERE ( attribute_name_ids && '{471}' ) AND NOT (
(attribute_name_ids||0) && '{471}') ;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on entity (cost=71.04..3432.73 rows=29881
width=126) (actual time=64.179..65.255 rows=1 loops=1)
Recheck Cond: (attribute_name_ids && '{471}'::integer[])
Filter: (NOT ((attribute_name_ids || 0) && '{471}'::integer[]))
Rows Removed by Filter: 8814
Heap Blocks: exact=7877
-> Bitmap Index Scan on entity_attribute_name_ids_gin
(cost=0.00..71.04 rows=30031 width=0) (actual time=10.396..10.398
rows=13628 loops=1)
Index Cond: (attribute_name_ids && '{471}'::integer[])
Planning Time: 0.164 ms
Execution Time: 65.458 ms
(9 rows)

When GIN is not used results are as expected:

data=# EXPLAIN ANALYZE SELECT entity_id,attribute_name_ids FROM
entity WHERE entity_id=197911914 AND attribute_name_ids && '{471}';
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------
Index Scan using entity_pkey on entity (cost=0.00..0.20 rows=1
width=126) (actual time=0.090..0.091 rows=0 loops=1)
Index Cond: (entity_id = 197911914)
Filter: (attribute_name_ids && '{471}'::integer[])
Rows Removed by Filter: 1
Planning Time: 0.233 ms
Execution Time: 0.116 ms
(6 rows)

data=# SELECT entity_id,attribute_name_ids FROM entity WHERE
entity_id=197911914 AND attribute_name_ids && '{471}';
entity_id | attribute_name_ids
-----------+--------------------
(0 rows)

From my observations introducing of misleading entry in GIN coincides
with update of database row that will be incorrectly reported.

Fixing the issue can be done by:

UPDATE entity SET attribute_name_ids ='{}' WHERE entity_id=197911914;
UPDATE entity SET attribute_name_ids
='{2,3,4,6,7,8,9,10,13,17,35,48,66,71,3270,3273,3279,4377,4842,5379,5787,7416}'
WHERE entity_id=197911914';

The table has following structure:

Column | Type | Collation |
Nullable | Default
-----------------------+--------------------------------+-----------+----------+---------------
entity_id | bigint | | not null |
attribute_value_ids | integer[] | | not null |
attribute_name_ids | integer[] | | not null |
[..]
Indexes:
"entity_pkey" PRIMARY KEY, btree (entity_id)
"entity_attribute_name_ids_gin" gin (attribute_name_ids gin__int_ops)
"entity_attribute_value_ids_gin" gin (attribute_value_ids gin__int_ops)
[..]

Disk footprint of it is ~ 60GB, ~38M rows. In fact it's a single table
in this database.

The table gets tens of millions of updates each day and maybe 10-100k
inserts with very little deletes.

I have taken a copy of database files from streaming replication slave
server. i also have WAL files from around the time that this
particular corruption occurred.

Is there any additional information I can provide?

thank you!

--
regards,
Pawel Kudzia