Обсуждение: xlog min recovery request 7C5C/96D5C550 is past current point
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 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
--
Victor Sudakov VAS4-RIPE
http://vas.tomsk.ru/
2:5005/49@fidonet
> 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
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