Date: Fri, 2 Jun 2023 08:11:15 +0000
From: Victor Sudakov <vas@sibptus.ru>
To: pgsql-admin@lists.postgresql.org
Subject: Re: xlog min recovery request 7C5C/96D5C550 is past current point
Message-ID: <ZHmkI7MJ13g2HblH@admin.sibptus.ru>
References: <ZHM+0CES5i0LEmTa@admin.sibptus.ru>
 <34465465.518828.1685474811496@office.mailbox.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <34465465.518828.1685474811496@office.mailbox.org>
Archived-At: 
 <https://www.postgresql.org/message-id/ZHmkI7MJ13g2HblH%40admin.sibptus.ru>
Precedence: bulk

Erik Wienhold wrote:
> > 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

Thanks for the links, and wow! If it is still the same problem it must
be at least 9 years old and noone has fixed it.

BTW seeing the messages not only about VM's, but about FSM's as well.

I only have to trust that these messages are indeed harmless. After
all, AFAIR VMs and FSMs will be rebuilt by autovacuum sooner or later. 


-- 
Victor Sudakov VAS4-RIPE
http://vas.tomsk.ru/
2:5005/49@fidonet