From: Tom Lane <tgl@sss.pgh.pa.us>
To: Thomas Munro <thomas.munro@gmail.com>
cc: =?UTF-8?Q?Dagfinn_Ilmari_Manns=C3=A5ker?= <ilmari@ilmari.org>,
        Simon Riggs <simon.riggs@enterprisedb.com>,
        Julien Rouhaud <rjuju123@gmail.com>,
        Ashutosh Sharma <ashu.coek88@gmail.com>,
        Daniel Gustafsson <daniel@yesql.se>,
        Stephen Frost <sfrost@snowman.net>,
        Alvaro Herrera <alvherre@2ndquadrant.com>,
        Andres Freund <andres@anarazel.de>,
 David Steele <david@pgmasters.net>,
        Dmitry Dolgov <9erthalion6@gmail.com>,
        Jakub Wartak <Jakub.Wartak@tomtom.com>,
        Tomas Vondra <tomas.vondra@2ndquadrant.com>,
        Tomas Vondra <tomas.vondra@enterprisedb.com>,
        pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: WIP: WAL prefetch (another approach)
In-reply-to: <111657.1650910309@sss.pgh.pa.us>
References: 
 <CA+hUKG+dE2-BOsZAQJC4miaXhZF3U6WV0cUH6yWJ+ixoiFNOSw@mail.gmail.com>
 <20220309064633.woyf53w3odnhltah@jrouhaud>
 <CA+hUKGKusWunqOd9En+FkT+US_kuDK-MSZyXHCr=OTwRw8Ah1A@mail.gmail.com>
 <20220311082737.bmnlmtzwi2xqrhxl@jrouhaud>
 <CA+hUKGKBxHZMVJFELZhC8iD57TBhboHtpmG+rzdOSdRGyxUGeQ@mail.gmail.com>
 <20220314071713.v4anmngdi5njaple@jrouhaud>
 <CA+hUKG+0Qe2b7eFancRmZcq1wAsFGizFVuq9bSAg5uNy+4wMiQ@mail.gmail.com>
 <CA+hUKGL=R4MMEX7DtFefnnT6v5Dun=Y=OWLCgD0_ixK2KkkKRw@mail.gmail.com>
 <20220321082916.ysrlw2xst2tpyc5a@jrouhaud>
 <CA+hUKGKs7cNkiMyNY9aSn2bF2AQNj9bb_dbY2B_6d_srnx5+mw@mail.gmail.com>
 <YkpiH3sFL8XsPBgs@jrouhaud>
 <CA+hUKGJ3aq3ZAxfhuPvMkOKwirfqunrV-p8d7kEe_WunjGndDw@mail.gmail.com>
 <CANbhV-FsVOXou11teGwPWiHh__yaDUSTG6K2JPRTHgznt2uvpg@mail.gmail.com>
 <87tuaynvka.fsf@wibble.ilmari.org>
 <CA+hUKGLtn-309+p6pFpR7AdQ+ypx7Zy=LhF6Bardie_bm-pb8Q@mail.gmail.com>
 <111657.1650910309@sss.pgh.pa.us>
Comments: In-reply-to Tom Lane <tgl@sss.pgh.pa.us>
	message dated "Mon, 25 Apr 2022 14:11:49 -0400"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <113604.1650911508.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Mon, 25 Apr 2022 14:31:48 -0400
Message-ID: <113605.1650911508@sss.pgh.pa.us>
Archived-At: 
 <https://www.postgresql.org/message-id/113605.1650911508%40sss.pgh.pa.us>
Precedence: bulk

Oh, one more bit of data: here's an excerpt from pg_waldump output after
the failed test:

rmgr: Btree       len (rec/tot):     72/    72, tx:        727, lsn: 0/019=
03BC8, prev 0/01903B70, desc: INSERT_LEAF off 111, blkref #0: rel 1663/163=
84/2673 blk 9
rmgr: Btree       len (rec/tot):     72/    72, tx:        727, lsn: 0/019=
03C10, prev 0/01903BC8, desc: INSERT_LEAF off 141, blkref #0: rel 1663/163=
84/2674 blk 7
rmgr: Standby     len (rec/tot):     42/    42, tx:        727, lsn: 0/019=
03C58, prev 0/01903C10, desc: LOCK xid 727 db 16384 rel 16391 =

rmgr: Transaction len (rec/tot):    437/   437, tx:        727, lsn: 0/019=
03C88, prev 0/01903C58, desc: COMMIT 2022-04-25 20:16:03.374197 CEST; inva=
l msgs: catcache 80 catcache 79 catcache 80 catcache 79 catcache 55 catcac=
he 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 ca=
tcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7=
 catcache 6 catcache 7 catcache 6 snapshot 2608 relcache 16391
rmgr: Heap        len (rec/tot):     59/    59, tx:        728, lsn: 0/019=
03E40, prev 0/01903C88, desc: INSERT+INIT off 1 flags 0x00, blkref #0: rel=
 1663/16384/16391 blk 0
rmgr: Heap        len (rec/tot):     59/    59, tx:        728, lsn: 0/019=
03E80, prev 0/01903E40, desc: INSERT off 2 flags 0x00, blkref #0: rel 1663=
/16384/16391 blk 0
rmgr: Transaction len (rec/tot):     34/    34, tx:        728, lsn: 0/019=
03EC0, prev 0/01903E80, desc: COMMIT 2022-04-25 20:16:03.379323 CEST
rmgr: Heap        len (rec/tot):     59/    59, tx:        729, lsn: 0/019=
03EE8, prev 0/01903EC0, desc: INSERT off 3 flags 0x00, blkref #0: rel 1663=
/16384/16391 blk 0
rmgr: Heap        len (rec/tot):     59/    59, tx:        729, lsn: 0/019=
03F28, prev 0/01903EE8, desc: INSERT off 4 flags 0x00, blkref #0: rel 1663=
/16384/16391 blk 0
rmgr: Transaction len (rec/tot):     34/    34, tx:        729, lsn: 0/019=
03F68, prev 0/01903F28, desc: COMMIT 2022-04-25 20:16:03.381720 CEST

The error is complaining about not being able to read 0/01903E40,
which AFAICT is from the first "INSERT INTO sample_tbl" command,
which most certainly ought to be down to disk at this point.

Also, I modified the test script to see what WAL LSNs it thought
it was dealing with, and got

+\echo 'wal_lsn1 =3D ' :wal_lsn1
+wal_lsn1 =3D  0/1903E40
+\echo 'wal_lsn2 =3D ' :wal_lsn2
+wal_lsn2 =3D  0/1903EE8

confirming that idea of where 0/01903E40 is in the WAL history.
So this is sure looking like a bug somewhere in xlogreader.c,
not in pg_walinspect.

			regards, tom lane