pg.ddx.io pgsql-hackers@postgresql.org mailing list archive help / color / mirror / Atom feed From: Justin Pryzby <pryzby@telsasoft.com>
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Cc: Shinoda, Noriyoshi (PN Japan FSIP) <noriyoshi.shinoda@hpe.com>
Cc: Tomas Vondra <tomas.vondra@enterprisedb.com>
Cc: Stephen Frost <sfrost@snowman.net>
Cc: Andres Freund <andres@anarazel.de>
Cc: Jakub Wartak <Jakub.Wartak@tomtom.com>
Cc: Alvaro Herrera <alvherre@2ndquadrant.com>
Cc: Tomas Vondra <tomas.vondra@2ndquadrant.com>
Cc: Dmitry Dolgov <9erthalion6@gmail.com>
Cc: David Steele <david@pgmasters.net>
Cc: pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: pg15b3: recovery fails with wal prefetch enabled
Date: Wed, 31 Aug 2022 23:47:53 -0500
Message-ID: <20220901044753.GG31833@telsasoft.com> (raw )
In-Reply-To: <CA+hUKGJ9pTgBzAVn38rAgOqse3E49g2ZtWfHDbon967a9p51ew@mail.gmail.com >
References: <20220831140128.GS31833@telsasoft.com >
<CA+hUKGKPG=yeV8=55KrhrTHBXROvH7z8i_vwxUw4KkrY2hkH7Q@mail.gmail.com >
<20220901.120804.504461198570722498.horikyota.ntt@gmail.com >
<CA+hUKGJ9pTgBzAVn38rAgOqse3E49g2ZtWfHDbon967a9p51ew@mail.gmail.com >
On Thu, Sep 01, 2022 at 04:22:20PM +1200, Thomas Munro wrote:
> On Thu, Sep 1, 2022 at 3:08 PM Kyotaro Horiguchi
> <horikyota.ntt@gmail.com> wrote:
> > At Thu, 1 Sep 2022 12:05:36 +1200, Thomas Munro <thomas.munro@gmail.com> wrote in
> > > On Thu, Sep 1, 2022 at 2:01 AM Justin Pryzby <pryzby@telsasoft.com> wrote:
> > > > < 2022-08-31 08:44:10.495 CDT >LOG: checkpoint starting: end-of-recovery immediate wait
> > > > < 2022-08-31 08:44:10.609 CDT >LOG: request to flush past end of generated WAL; request 1201/1CAF84F0, current position 1201/1CADB730
> > > > < 2022-08-31 08:44:10.609 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
> > > > < 2022-08-31 08:44:10.609 CDT >ERROR: xlog flush request 1201/1CAF84F0 is not satisfied --- flushed only to 1201/1CADB730
> > > > < 2022-08-31 08:44:10.609 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
> > > > < 2022-08-31 08:44:10.609 CDT >FATAL: checkpoint request failed
> > > >
> > > > I was able to start it with -c recovery_prefetch=no, so it seems like
> > > > prefetch tried to do too much. The VM runs centos7 under qemu.
> > > > I'm making a copy of the data dir in cases it's needed.
> >
> > Just for information, there was a fixed bug about
> > overwrite-aborted-contrecord feature, which causes this kind of
> > failure (xlog flush request exceeds insertion bleeding edge). If it is
> > that, it has been fixed by 6672d79139 two-days ago.
>
> Hmm. Justin, when you built from source, which commit were you at?
> If it's REL_15_BETA3,
No - it's:
commit a2039b1f8e90d26a7e2a115ad5784476bd6deaa2 (HEAD -> REL_15_STABLE, origin/REL_15_STABLE)
> If it's REL_15_BETA3, any chance you could cherry pick that change and
> check what happens? And without that, could you show what this logs
> And without that, could you show what this logs
> for good and bad recovery settings?
I wasn't sure what mean by "without that" , so here's a bunch of logs to
sift through:
At a203, with #define XLOGPREFETCHER_DEBUG_LEVEL NOTICE:
[pryzbyj@template0 postgresql]$ sudo -u postgres ./tmp_install/usr/local/pgsql/bin/postgres -D /mnt/tmp/15/data -c logging_collector=no -c port=5678
...
< 2022-08-31 23:31:38.690 CDT >LOG: redo starts at 1201/1B931F50
< 2022-08-31 23:31:40.204 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958212 from block 156 until 1201/1C3965A0 is replayed, which truncates the relation
< 2022-08-31 23:31:40.307 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958523 from block 23 until 1201/1C39CC98 is replayed, which truncates the relation
< 2022-08-31 23:31:40.493 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958523 from block 23 until 1201/1C8643C8 is replayed, because the relation is too small
< 2022-08-31 23:31:40.721 CDT >LOG: redo done at 1201/1CADB300 system usage: CPU: user: 0.41 s, system: 0.23 s, elapsed: 2.03 s
< 2022-08-31 23:31:41.452 CDT >LOG: checkpoint starting: end-of-recovery immediate wait
< 2022-08-31 23:31:41.698 CDT >LOG: request to flush past end of generated WAL; request 1201/1CAF84F0, current position 1201/1CADB730
< 2022-08-31 23:31:41.698 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
< 2022-08-31 23:31:41.698 CDT >ERROR: xlog flush request 1201/1CAF84F0 is not satisfied --- flushed only to 1201/1CADB730
< 2022-08-31 23:31:41.698 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
< 2022-08-31 23:31:41.699 CDT >FATAL: checkpoint request failed
< 2022-08-31 23:31:41.699 CDT >HINT: Consult recent messages in the server log for details.
< 2022-08-31 23:31:41.704 CDT >LOG: startup process (PID 25046) exited with exit code 1
< 2022-08-31 23:31:41.704 CDT >LOG: terminating any other active server processes
< 2022-08-31 23:31:41.705 CDT >LOG: shutting down due to startup process failure
< 2022-08-31 23:31:41.731 CDT >LOG: database system is shut down
With your patch:
[pryzbyj@template0 postgresql]$ sudo -u postgres ./tmp_install/usr/local/pgsql/bin/postgres -D /mnt/tmp/15/data -c logging_collector=no -c port=5678
...
< 2022-08-31 23:34:22.897 CDT >LOG: redo starts at 1201/1B931F50
< 2022-08-31 23:34:23.146 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958212 from block 156 until 1201/1C3965A0 is replayed, which truncates the relation
< 2022-08-31 23:34:23.147 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958523 from block 23 until 1201/1C39CC98 is replayed, which truncates the relation
< 2022-08-31 23:34:23.268 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958523 from block 23 until 1201/1C8643C8 is replayed, because the relation is too small
< 2022-08-31 23:34:23.323 CDT >LOG: redo done at 1201/1CADB300 system usage: CPU: user: 0.29 s, system: 0.12 s, elapsed: 0.42 s
< 2022-08-31 23:34:23.323 CDT >LOG: point 0: lastRec = 12011cadb300
< 2022-08-31 23:34:23.323 CDT >LOG: point 0: endOfLog = 12011cadb730
< 2022-08-31 23:34:23.323 CDT >LOG: XXX point 1: EndOfLog = 12011cadb730
< 2022-08-31 23:34:23.386 CDT >LOG: XXX point 2: EndOfLog = 12011cadb730
< 2022-08-31 23:34:23.387 CDT >LOG: XXX point 3: Insert->CurrBytePos = 11f39ab82310
< 2022-08-31 23:34:23.565 CDT >LOG: XXX point 4: Insert->CurrBytePos = 11f39ab82310
< 2022-08-31 23:34:23.606 CDT >LOG: checkpoint starting: end-of-recovery immediate wait
< 2022-08-31 23:34:23.767 CDT >LOG: request to flush past end of generated WAL; request 1201/1CAF84F0, current position 1201/1CADB730
< 2022-08-31 23:34:23.767 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
< 2022-08-31 23:34:23.767 CDT >ERROR: xlog flush request 1201/1CAF84F0 is not satisfied --- flushed only to 1201/1CADB730
< 2022-08-31 23:34:23.767 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
< 2022-08-31 23:34:23.768 CDT >FATAL: checkpoint request failed
And without prefetch:
[pryzbyj@template0 postgresql]$ sudo -u postgres ./tmp_install/usr/local/pgsql/bin/postgres -D /mnt/tmp/15/data -c logging_collector=no -c port=5678 -c recovery_prefetch=no
...
< 2022-08-31 23:37:08.792 CDT >LOG: redo starts at 1201/1B931F50
< 2022-08-31 23:37:09.269 CDT >LOG: invalid record length at 1201/1CD91010: wanted 24, got 0
< 2022-08-31 23:37:09.269 CDT >LOG: redo done at 1201/1CD90E48 system usage: CPU: user: 0.35 s, system: 0.11 s, elapsed: 0.47 s
< 2022-08-31 23:37:09.269 CDT >LOG: point 0: lastRec = 12011cd90e48
< 2022-08-31 23:37:09.269 CDT >LOG: point 0: endOfLog = 12011cd91010
< 2022-08-31 23:37:09.269 CDT >LOG: XXX point 1: EndOfLog = 12011cd91010
< 2022-08-31 23:37:09.350 CDT >LOG: XXX point 2: EndOfLog = 12011cd91010
< 2022-08-31 23:37:09.350 CDT >LOG: XXX point 3: Insert->CurrBytePos = 11f39ae35b68
< 2022-08-31 23:37:09.420 CDT >LOG: XXX point 4: Insert->CurrBytePos = 11f39ae35b68
< 2022-08-31 23:37:09.552 CDT >LOG: checkpoint starting: end-of-recovery immediate wait
< 2022-08-31 23:37:12.987 CDT >LOG: checkpoint complete: wrote 8030 buffers (49.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.403 s, sync=2.841 s, total=3.566 s; sync files=102, longest=2.808 s, average=0.028 s; distance=20860 kB, estimate=20860 kB
< 2022-08-31 23:37:13.077 CDT >LOG: database system is ready to accept connections
If I revert 6672d79139 (and roll back to the unrecovered state):
[pryzbyj@template0 postgresql]$ sudo -u postgres ./tmp_install/usr/local/pgsql/bin/postgres -D /mnt/tmp/15/data -c logging_collector=no -c port=5678 # -c recovery_prefetch=no
...
< 2022-08-31 23:42:40.592 CDT >LOG: redo starts at 1201/1B931F50
< 2022-08-31 23:42:42.168 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958212 from block 156 until 1201/1C3965A0 is replayed, which truncates the relation
< 2022-08-31 23:42:42.238 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958523 from block 23 until 1201/1C39CC98 is replayed, which truncates the relation
< 2022-08-31 23:42:42.405 CDT >NOTICE: suppressing prefetch in relation 1663/16888/165958523 from block 23 until 1201/1C8643C8 is replayed, because the relation is too small
< 2022-08-31 23:42:42.602 CDT >LOG: redo done at 1201/1CADB300 system usage: CPU: user: 0.41 s, system: 0.25 s, elapsed: 2.01 s
< 2022-08-31 23:42:42.602 CDT >LOG: point 0: lastRec = 12011cadb300
< 2022-08-31 23:42:42.602 CDT >LOG: point 0: endOfLog = 12011cadb730
< 2022-08-31 23:42:42.602 CDT >LOG: XXX point 1: EndOfLog = 12011cadb730
< 2022-08-31 23:42:42.830 CDT >LOG: XXX point 2: EndOfLog = 12011cadb730
< 2022-08-31 23:42:42.830 CDT >LOG: XXX point 3: Insert->CurrBytePos = 11f39ab82310
< 2022-08-31 23:42:43.194 CDT >LOG: XXX point 4: Insert->CurrBytePos = 11f39ab82310
< 2022-08-31 23:42:43.266 CDT >LOG: checkpoint starting: end-of-recovery immediate wait
< 2022-08-31 23:42:43.425 CDT >LOG: request to flush past end of generated WAL; request 1201/1CAF84F0, current position 1201/1CADB730
< 2022-08-31 23:42:43.425 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
< 2022-08-31 23:42:43.425 CDT >ERROR: xlog flush request 1201/1CAF84F0 is not satisfied --- flushed only to 1201/1CADB730
< 2022-08-31 23:42:43.425 CDT >CONTEXT: writing block 0 of relation base/16881/2840_vm
< 2022-08-31 23:42:43.425 CDT >FATAL: checkpoint request failed
< 2022-08-31 23:42:43.425 CDT >HINT: Consult recent messages in the server log for details.
< 2022-08-31 23:42:43.431 CDT >LOG: startup process (PID 2415) exited with exit code 1
< 2022-08-31 23:42:43.431 CDT >LOG: terminating any other active server processes
< 2022-08-31 23:42:43.432 CDT >LOG: shutting down due to startup process failure
< 2022-08-31 23:42:43.451 CDT >LOG: database system is shut down
If I revert 6672d79139 and disable prefetch:
[pryzbyj@template0 postgresql]$ sudo -u postgres ./tmp_install/usr/local/pgsql/bin/postgres -D /mnt/tmp/15/data -c logging_collector=no -c port=5678 -c recovery_prefetch=no
...
< 2022-08-31 23:43:25.711 CDT >LOG: redo starts at 1201/1B931F50
< 2022-08-31 23:43:26.178 CDT >LOG: invalid record length at 1201/1CD91010: wanted 24, got 0
< 2022-08-31 23:43:26.178 CDT >LOG: redo done at 1201/1CD90E48 system usage: CPU: user: 0.33 s, system: 0.11 s, elapsed: 0.46 s
< 2022-08-31 23:43:26.178 CDT >LOG: point 0: lastRec = 12011cd90e48
< 2022-08-31 23:43:26.178 CDT >LOG: point 0: endOfLog = 12011cd91010
< 2022-08-31 23:43:26.178 CDT >LOG: XXX point 1: EndOfLog = 12011cd91010
< 2022-08-31 23:43:26.369 CDT >LOG: XXX point 2: EndOfLog = 12011cd91010
< 2022-08-31 23:43:26.369 CDT >LOG: XXX point 3: Insert->CurrBytePos = 11f39ae35b68
< 2022-08-31 23:43:26.433 CDT >LOG: XXX point 4: Insert->CurrBytePos = 11f39ae35b68
< 2022-08-31 23:43:26.490 CDT >LOG: checkpoint starting: end-of-recovery immediate wait
< 2022-08-31 23:43:29.519 CDT >LOG: checkpoint complete: wrote 8030 buffers (49.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.380 s, sync=2.492 s, total=3.086 s; sync files=102, longest=2.438 s, average=0.025 s; distance=20860 kB, estimate=20860 kB
< 2022-08-31 23:43:29.567 CDT >LOG: database system is ready to accept connections
view thread (25+ messages) latest in thread
Message-ID: <20220901044753.GG31833@telsasoft.com>
Permalink: ../20220901044753.GG31833@telsasoft.com/
Also on: postgresql.org/message-id/20220901044753.GG31833@telsasoft.com
copy link · copy postgr.es
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: pryzby@telsasoft.com, thomas.munro@gmail.com, horikyota.ntt@gmail.com, noriyoshi.shinoda@hpe.com, tomas.vondra@enterprisedb.com, sfrost@snowman.net, andres@anarazel.de, Jakub.Wartak@tomtom.com, alvherre@2ndquadrant.com, tomas.vondra@2ndquadrant.com, 9erthalion6@gmail.com, david@pgmasters.net
Subject: Re: pg15b3: recovery fails with wal prefetch enabled
In-Reply-To: <20220901044753.GG31833@telsasoft.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox