Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nj3C0-0005KE-1d for pgsql-hackers@arkaria.postgresql.org; Mon, 25 Apr 2022 18:12:12 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1nj3Bx-0008Bt-6R for pgsql-hackers@arkaria.postgresql.org; Mon, 25 Apr 2022 18:12:09 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nj3Bw-0008Bk-TA for pgsql-hackers@lists.postgresql.org; Mon, 25 Apr 2022 18:12:08 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nj3Bt-0002ox-EL for pgsql-hackers@postgresql.org; Mon, 25 Apr 2022 18:12:08 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 23PIBnhk111658; Mon, 25 Apr 2022 14:11:49 -0400 From: Tom Lane To: Thomas Munro cc: =?UTF-8?Q?Dagfinn_Ilmari_Manns=C3=A5ker?= , Simon Riggs , Julien Rouhaud , Ashutosh Sharma , Daniel Gustafsson , Stephen Frost , Alvaro Herrera , Andres Freund , David Steele , Dmitry Dolgov <9erthalion6@gmail.com>, Jakub Wartak , Tomas Vondra , Tomas Vondra , pgsql-hackers Subject: Re: WIP: WAL prefetch (another approach) In-reply-to: References: <20220309064633.woyf53w3odnhltah@jrouhaud> <20220311082737.bmnlmtzwi2xqrhxl@jrouhaud> <20220314071713.v4anmngdi5njaple@jrouhaud> <20220321082916.ysrlw2xst2tpyc5a@jrouhaud> <87tuaynvka.fsf@wibble.ilmari.org> Comments: In-reply-to Thomas Munro message dated "Wed, 13 Apr 2022 08:05:11 +1200" MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-ID: <111656.1650910309.1@sss.pgh.pa.us> Content-Transfer-Encoding: quoted-printable Date: Mon, 25 Apr 2022 14:11:49 -0400 Message-ID: <111657.1650910309@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk I believe that the WAL prefetch patch probably accounts for the intermittent errors that buildfarm member topminnow has shown since it went in, eg [1]: diff -U3 /home/nm/ext4/HEAD/pgsql/contrib/pg_walinspect/expected/pg_walins= pect.out /home/nm/ext4/HEAD/pgsql.build/contrib/pg_walinspect/results/pg_w= alinspect.out --- /home/nm/ext4/HEAD/pgsql/contrib/pg_walinspect/expected/pg_walinspect.= out 2022-04-10 03:05:15.972622440 +0200 +++ /home/nm/ext4/HEAD/pgsql.build/contrib/pg_walinspect/results/pg_walins= pect.out 2022-04-25 05:09:49.861642059 +0200 @@ -34,11 +34,7 @@ (1 row) = SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal= (:'wal_lsn1'); - ok = ----- - t -(1 row) - +ERROR: could not read WAL at 0/1903E40 SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_stats(:'wal_lsn1', :'wal_lsn= 2'); ok = ---- @@ -46,11 +42,7 @@ (1 row) = SELECT COUNT(*) >=3D 0 AS ok FROM pg_get_wal_stats_till_end_of_wal(:'wal_= lsn1'); - ok = ----- - t -(1 row) - +ERROR: could not read WAL at 0/1903E40 -- =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D -- Test for filtering out WAL records of a particular table -- =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D I've reproduced this manually on that machine, and confirmed that the proximate cause is that XLogNextRecord() is returning NULL because state->decode_queue_head =3D=3D NULL, without bothering to provide an erro= rmsg (which doesn't seem very well thought out in itself). I obtained the contents of the xlogreader struct at failure: (gdb) p *xlogreader $1 =3D {routine =3D {page_read =3D 0x594270 = , = segment_open =3D 0x593b44 , = segment_close =3D 0x593d38 }, system_identifier =3D= 0, = private_data =3D 0x0, ReadRecPtr =3D 26230672, EndRecPtr =3D 26230752, = abortedRecPtr =3D 26230752, missingContrecPtr =3D 26230784, = overwrittenRecPtr =3D 0, DecodeRecPtr =3D 26230672, NextRecPtr =3D 26230= 752, = PrevRecPtr =3D 0, record =3D 0x0, decode_buffer =3D 0xf25428 "\240", = decode_buffer_size =3D 65536, free_decode_buffer =3D true, = decode_buffer_head =3D 0xf25428 "\240", decode_buffer_tail =3D 0xf25428 = "\240", = decode_queue_head =3D 0x0, decode_queue_tail =3D 0x0, = readBuf =3D 0xf173f0 "\020\321\005", readLen =3D 0, segcxt =3D { ws_dir =3D '\000' , ws_segsize =3D 16777216}, seg = =3D { ws_file =3D 25, ws_segno =3D 0, ws_tli =3D 1}, segoff =3D 0, = latestPagePtr =3D 26222592, latestPageTLI =3D 1, currRecPtr =3D 26230752= , = currTLI =3D 1, currTLIValidUntil =3D 0, nextTLI =3D 0, = readRecordBuf =3D 0xf1b3f8 "<", readRecordBufSize =3D 40960, = errormsg_buf =3D 0xef3270 "", errormsg_deferred =3D false, nonblocking =3D= false} I don't have an intuition about where to look beyond that, any suggestions? What I do know so far is that while the failure reproduces fairly reliably under "make check" (more than half the time, which squares with topminnow's history), it doesn't reproduce at all under "make installcheck" (after removing NO_INSTALLCHECK), which seems odd. Maybe it's dependent on how much WAL history the installation has accumulated? It could be that this is a bug in pg_walinspect or a fault in its test case; hard to tell since that got committed at about the same time as the prefetch changes. regards, tom lane [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dtopminnow&dt= =3D2022-04-25%2001%3A48%3A47