From: Ronan Dunklau <ronan.dunklau@aiven.io>
To: Noah Misch <noah@leadboat.com>
Cc: pgsql-bugs <pgsql-bugs@lists.postgresql.org>
Subject: Re: FSM Corruption (was: Could not read block at end of the relation)
Date: Mon, 04 Mar 2024 14:10:39 +0100
Message-ID: <1925490.taCxCBeP46@aivenlaptop>
In-Reply-To: <20240303234715.4d@rfd.leadboat.com>
References: 
 <VtPLBUerbMM8BSDLQwIMV9Co_38iHS1TXE4V09x2ZVFhPkZMNE8LwgPSIzB8PHkVFXykGx04QNAzZVjJFAnU1w==@protonmail.internalid>
 <1958255.PYKUYFuaPT@aivenlaptop> <20240303234715.4d@rfd.leadboat.com>
MIME-Version: 1.0
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain; charset="iso-8859-1"
Archived-At: 
 <https://www.postgresql.org/message-id/1925490.taCxCBeP46%40aivenlaptop>
Precedence: bulk

Le lundi 4 mars 2024, 00:47:15 CET Noah Misch a =E9crit :
> On Tue, Feb 27, 2024 at 11:34:14AM +0100, Ronan Dunklau wrote:
> > - happens during heavy system load
> > - lots of concurrent writes happening on a table
> > - often (but haven't been able to confirm it is necessary), a vacuum is
> > running on the table at the same time the error is triggered
> >=20
> > Then, several backends get the same error at once "ERROR:  could not re=
ad
> > block XXXX in file "base/XXXX/XXXX": read only 0 of 8192 bytes", with
> > different
> What are some of the specific block numbers reported?

Nothing specific, except they are past the end of the table, by an offset=20
starting at one. I've seen it happens on regular tables restored by pg_rest=
ore=20
quite a lot, but also on bigger tables, regular or TOAST. We've seen this o=
n a=20
dozen different clusters, but nothing reproducible for now.=20

>=20
> > has anybody witnessed something similar ?
>=20
> https://postgr.es/m/flat/CA%2BhUKGK%2B5DOmLaBp3Z7C4S-Yv6yoROvr1UncjH2S1Zb=
PT8
> D%2BZg%40mail.gmail.com reminded me of this.  Did you upgrade your OS
> recently?

No recent upgrades I'm aware of. Also, it only touches PG16 clusters, not=20
earlier versions. But it looks like the same kind of errors.=20


> What corruption signs did you observe in the FSM?  Since FSM is
> intentionally not WAL-logged, corruption is normal, but corruption causing
> errors is not normal.  That said, if any crash leaves a state that the
> freespace/README "self-correcting measures" don't detect, errors may
> happen.  Did the clusters crash recently?

Well we still have full page images for the FSM.=20
I'll take as an example the cluster I'm currently investigating on.
The corruption I'm seeing is that I have an additional entry in the FSM for=
 a=20
block that does not exist in the relation: IIUC, slot 4129 corresponds to=20
block 34, which is the last one I have in the relation. However, I have an=
=20
entry (slot 4130) for block number 35, with MaxFSMRequestSize=20

 fsm_page_contents=20
=2D------------------
 0: 255           +
 1: 255           +
 3: 255           +
=2E..
 4129: 114        +
 4130: 255        +


This then causes attempts to insert into that block to fail.=20

Looking at when the corruption was WAL-logged, this particular case is quit=
e=20
easy to trace. We have a few MULTI-INSERTS+INIT intiially loading the table=
=20
(probably a pg_restore), then, 2GB of WAL later, what looks like a VACUUM=20
running on the table: a succession of FPI_FOR_HINT, FREEZE_PAGE, VISIBLE xl=
og=20
records for each of the relation main fork, followed by a lonely FPI for th=
e=20
leaf page of it's FSM:

rmgr: Heap2       len (rec/tot):   5698/  5698, tx:       1637, lsn:=20
1/810763B8, prev 1/81076388, desc: MULTI_INSERT+INIT ntuples: 124, flags: 0=
x08,=20
blkref #0: rel 1663/17343/17959 blk 0
rmgr: XLOG        len (rec/tot):     49/  8241, tx:       1637, lsn:=20
1/81077A00, prev 1/810763B8, desc: FPI_FOR_HINT , blkref #0: rel=20
1663/17343/17959 fork fsm blk 2 FPW
rmgr: Heap2       len (rec/tot):   5762/  5762, tx:       1637, lsn:=20
1/81079A50, prev 1/81077A00, desc: MULTI_INSERT+INIT ntuples: 121, flags: 0=
x08,=20
blkref #0: rel 1663/17343/17959 blk 1
rmgr: Heap2       len (rec/tot):   5746/  5746, tx:       1637, lsn:=20
1/8107B0F0, prev 1/81079A50, desc: MULTI_INSERT+INIT ntuples: 121, flags: 0=
x08,=20
blkref #0: rel 1663/17343/17959 blk 2
rmgr: Heap2       len (rec/tot):   5778/  5778, tx:       1637, lsn:=20
1/8107C780, prev 1/8107B0F0, desc: MULTI_INSERT+INIT ntuples: 121, flags: 0=
x08,=20
blkref #0: rel 1663/17343/17959 blk 3

(up until blk 34 is  wal logged)

At some point pages 0 and 1 get a FPI, the leaf page (blk2) does not during=
=20
the transaction.

Later on, we have this for every main fork block:

rmgr: XLOG        len (rec/tot):     49/  8201, tx:          0, lsn:=20
2/0E1ECEC8, prev 2/0E1ECE10, desc: FPI_FOR_HINT , blkref #0: rel=20
1663/17343/17959 blk 0 FPW
rmgr: Heap2       len (rec/tot):    325/   325, tx:          0, lsn:=20
2/0E1EEEF0, prev 2/0E1ECEC8, desc: FREEZE_PAGE snapshotConflictHorizon: 163=
7,=20
nplans: 2, plans: [{ xmax: 0, infomask: 2816, infomask2: 5, ntuples: 86,=20
offsets: [1, 2, 3, 5, 7, 10, 14, 16, 21, 22, 28, 30, 31, 32, 33, 34, 35, 36=
,=20
37, 38, 39, 40, 41, 42, 45, 46, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 60,=
=20
64, 65, 67, 68, 69, 71, 72, 73, 74, 75, 76, 77, 78, 79, 81, 82, 83, 85, 86,=
=20
87, 90, 92, 94, 95, 96, 98, 100, 102, 103, 104, 105, 106, 107, 108, 109, 11=
0,=20
111, 112, 113, 114, 115, 117, 118, 119, 120, 121, 122, 123, 124] }, { xmax:=
 0,=20
infomask: 2817, infomask2: 5, ntuples: 38, offsets: [4, 6, 8, 9, 11, 12, 13=
,=20
15, 17, 18, 19, 20, 23, 24, 25, 26, 27, 29, 43, 44, 47, 48, 59, 61, 62, 63,=
=20
66, 70, 80, 84, 88, 89, 91, 93, 97, 99, 101, 116] }], blkref #0: rel=20
1663/17343/17959 blk 0
rmgr: Heap2       len (rec/tot):     64/  8256, tx:          0, lsn:=20
2/0E1EF038, prev 2/0E1EEEF0, desc: VISIBLE snapshotConflictHorizon: 0, flag=
s:=20
0x03, blkref #0: rel 1663/17343/17959 fork vm blk 0 FPW, blkref #1: rel=20
1663/17343/17959 blk 0


And then the single FSM FPI, which contains the invalid record:

rmgr: XLOG        len (rec/tot):     49/  8241, tx:          0, lsn:=20
2/0E28F640, prev 2/0E28F600, desc: FPI_FOR_HINT , blkref #0: rel=20
1663/17343/17959 fork fsm blk 2 FPW

I've dumped the associated FPIs, and took a look at them. First FPI for lea=
f=20
block (#2 in the fsm) happens in the beginning of the multi insert=20
transaction, and only contains one leaf node for block 0 (slot 4095).

Later FPI (during what I think is a VACUUM) persists the corruption in the=
=20
WAL.=20
So presumably something happened during the COPY operation which caused it =
to=20
add an invalid entry for inexisting block 35 in the FSM.=20

There are no traces of relation truncation happening in the WAL.=20

This case only shows a single invalid entry in the FSM, but I've noticed as=
=20
much as 62 blocks present in the FSM while they do not exist on disk, all=20
tagged with MaxFSMRequestSize so I suppose something is wrong with the bulk=
=20
extension mechanism.


>=20
> > The occurence of this bug happening makes it hard to reproduce,  but it=
's
> > definitely frequent enough we witnessed it on a dozen PostgreSQL cluste=
rs.
>=20
> You could do "ALTER TABLE x SET (vacuum_truncate =3D off);" and see if the
> problem stops happening.  That would corroborate the VACUUM theory.
>=20
> Can you use backtrace_functions to get a stack track?

I got a stack trace from the error after the corruption has occured (even g=
ot=20
to attach gdb to it as I was able to restore a corrupted cluster), but I do=
n't=20
think it's of any use (this is from a different occurence than the one I wr=
ote=20
in details above, so the block numbers don't match but it's the exact same=
=20
thing).

#0  errstart (elevel=3D21, domain=3D0x0) at utils/error/elog.c:348
#1  0x000055c81ea83a0a in errstart_cold (domain=3D0x0, elevel=3D21) at util=
s/
error/elog.c:333
#2  mdread (reln=3D0x55c8210bbe00, forknum=3DMAIN_FORKNUM, blocknum=3D1203,=
=20
buffer=3D0x7f51b4c32000) at storage/smgr/md.c:796
#3  0x000055c81ee396cf in smgrread (buffer=3D0x7f51b4c32000, blocknum=3D120=
3,=20
forknum=3DMAIN_FORKNUM, reln=3D0x55c8210bbe00) at storage/smgr/smgr.c:565
#4  ReadBuffer_common (smgr=3D0x55c8210bbe00,=20
relpersistence=3Drelpersistence@entry=3D112 'p',=20
forkNum=3DforkNum@entry=3DMAIN_FORKNUM, blockNum=3DblockNum@entry=3D1203,=20
    mode=3Dmode@entry=3DRBM_NORMAL, strategy=3D<optimized out>, hit=3D0x7ff=
f6e22f607)=20
at storage/buffer/bufmgr.c:1124
#5  0x000055c81ee39d0b in ReadBufferExtended (reln=3D0x7f51b294f0d0,=20
forkNum=3DMAIN_FORKNUM, blockNum=3D1203, mode=3DRBM_NORMAL, strategy=3D<opt=
imized=20
out>)
    at access/brin/../../../../src/include/utils/rel.h:576
#6  0x000055c81eb1525c in ReadBufferBI (mode=3DRBM_NORMAL, bistate=3D0x0,=20
targetBlock=3D1203, relation=3D<optimized out>) at access/heap/hio.c:96
#7  RelationGetBufferForTuple (relation=3D<optimized out>, len=3D<optimized=
 out>,=20
otherBuffer=3D0, options=3D<optimized out>, bistate=3D0x0, vmbuffer=3D<opti=
mized out>,=20
    vmbuffer_other=3D<optimized out>, num_pages=3D<optimized out>) at acces=
s/heap/
hio.c:620
#8  0x000055c81eafcace in heap_insert (relation=3D0x7f51b294f0d0,=20
tup=3D0x55c821042580, cid=3D<optimized out>, options=3D0, bistate=3D0x0) at=
 access/
heap/heapam.c:1862
#9  0x000055c81eb08bab in heapam_tuple_insert (relation=3D0x7f51b294f0d0,=20
slot=3D0x55c821042478, cid=3D0, options=3D0, bistate=3D0x0) at access/heap/
heapam_handler.c:252
#10 0x000055c81ecce2f1 in table_tuple_insert (bistate=3D0x0, options=3D0,=20
cid=3D<optimized out>, slot=3D0x55c821042478, rel=3D<optimized out>)
    at executor/../../../src/include/access/tableam.h:1400
#11 ExecInsert (context=3Dcontext@entry=3D0x7fff6e22f9b0,=20
resultRelInfo=3DresultRelInfo@entry=3D0x55c8210410c0,=20
slot=3Dslot@entry=3D0x55c821042478, canSetTag=3D<optimized out>,=20
    inserted_tuple=3Dinserted_tuple@entry=3D0x0,=20
insert_destrel=3Dinsert_destrel@entry=3D0x0) at executor/nodeModifyTable.c:=
1133
#12 0x000055c81eccf1eb in ExecModifyTable (pstate=3D<optimized out>) at=20
executor/nodeModifyTable.c:3810

Just a regular insertion failing to read the block it's trying to insert in=
to.

> > In our case, we need to repair the FSM. The instructions on the wiki do
> > work, but maybe we should add something like the attached patch (modeled
> > after the same feature in pg_visibility) to make it possible to repair
> > the FSM corruption online. What do you think about it ?
>=20
> That's reasonable in concept.

Ok, I'll start a separate thread on -hackers for that.=20

Thank you !