Date: Tue, 30 May 2023 21:26:51 +0200 (CEST)
From: Erik Wienhold <ewie@ewie.name>
To: Victor Sudakov <vas@sibptus.ru>, pgsql-admin@lists.postgresql.org
Message-ID: <34465465.518828.1685474811496@office.mailbox.org>
In-Reply-To: <ZHM+0CES5i0LEmTa@admin.sibptus.ru>
References: <ZHM+0CES5i0LEmTa@admin.sibptus.ru>
Subject: Re: xlog min recovery request 7C5C/96D5C550 is past current point
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
Importance: Normal
Archived-At: 
 <https://www.postgresql.org/message-id/34465465.518828.1685474811496%40office.mailbox.org>
Precedence: bulk

> On 28/05/2023 13:45 CEST Victor Sudakov <vas@sibptus.ru> wrote:
>
> Dear Colleagues,
>
> After starting a Postgres 13.11 cluster from a pg_basebackup'ed
> directory, it started its recovery with lots of these messages in the log:
>
> 2024-05-26 03:30:26.526 MST [394116] WARNING:  xlog min recovery request 7C5B/8AC06EA0 is past current point 7C5B/839449E8
> 2023-05-26 03:30:26.526 MST [394116] CONTEXT:  writing block 23 of relation base/1653520455/1653526563_fsm
>         WAL redo at 7C5B/83944978 for Heap/UPDATE: off 126 xmax 1873090085 flags 0x02 ; new off 3 xmax 0
> 2023-05-26 03:30:30.438 MST [394116] WARNING:  xlog min recovery request 7C5B/8AC06EA0 is past current point 7C5B/8847C348
> 2023-05-26 03:30:30.438 MST [394116] CONTEXT:  writing block 23 of relation base/1653520455/1653526563_fsm
>         WAL redo at 7C5B/8847A420 for XLOG/FPI_FOR_HINT:
> 2023-05-26 03:30:33.612 MST [394116] WARNING:  xlog min recovery request 7C5B/BD1CC550 is past current point 7C5B/8A3CF248
> 2023-05-26 03:30:33.612 MST [394116] CONTEXT:  writing block 2 of relation base/1653520455/1653527229_fsm
>         WAL redo at 7C5B/8A3CF208 for Heap2/VISIBLE: cutoff xid 1873088629 flags 0x01
> 2023-05-26 03:30:42.836 MST [394116] WARNING:  xlog min recovery request 7C5B/BA11C7D8 is past current point 7C5B/8C7830E8
> 2023-05-26 03:30:42.836 MST [394116] CONTEXT:  writing block 0 of relation base/1653520455/1653554782_vm
>         WAL redo at 7C5B/8C7830B0 for Heap2/CLEAN: remxid 1873090422
> 2023-05-26 03:30:48.174 MST [394116] WARNING:  xlog min recovery request 7C5C/3E4F06F8 is past current point 7C5B/8EC92C70
> 2023-05-26 03:30:48.174 MST [394116] CONTEXT:  writing block 126 of relation base/1653520455/1653524986_fsm
>         WAL redo at 7C5B/8EC92B90 for Heap2/CLEAN: remxid 1873087613
>
>
> Eventually the cluster reached the consistent state and reported
> "ready to accept connections" but I'm wondering what could have caused
> these messages and what they are about. Googling did not bring much
> enlightenment.
>
> Most of these messages seem to be about the FSMs, but not all of them. 
>
> Any ideas? Should I be worried?

The relevant code comment says that corrupted heap pages could be the cause. [0]
But searching the lists I found [1] which names the visibility map code as one
cause.  But this is just a guess, I don't know if that explanation is still
valid.

[0] https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/backend/access/transam/xlog.c;h=a1ceded9e092f40e2559a020bd9675856a428edb;hb=2faab87390b03929a8cbb5a9336a04faa45a27c5#l2823
[1] https://www.postgresql.org/message-id/CAB7nPqTQkW%2BFZYQbbPBoaoge1HkQCD7gxKfGGigF6E88mvYKfw%40mail.gmail.com

> The basebackup command was very simple, I was actually making a copy
> of the running cluster for experimental purposes to another zpool:
>
> pg_basebackup -D /pg_data0/13/test2 -c fast -X stream -U repmgr -P

--
Erik