Re: xlog min recovery request ... is past current point ...

On 03.02.2012 18:32, Christophe Pettus wrote:
> PostgreSQL 9.0.4:
>
> While bringing up a streaming replica, and while it is working its way through the WAL segments before connecting to the primary, I see a lot of messages of the form:
>
> 2012-02-01 21:26:13.978 PST,,,24448,,4f2a1e61.5f80,54,,2012-02-01 21:25:53 PST,1/0,0,LOG,00000,"restored log file ""0000000100000DB400000065"" from archive",,,,,,,,,""
> 2012-02-01 21:26:14.032 PST,,,24448,,4f2a1e61.5f80,55,,2012-02-01 21:25:53 PST,1/0,0,WARNING,01000,"xlog min recovery request DB5/42E15098 is past current point DB4/657FA490",,,,,"writing block 5 of relation base/155650/156470_vm
> xlog redo insert: rel 1663/155650/1658867; tid 9640/53",,,,""
> 2012-02-01 21:26:14.526 PST,,,24448,,4f2a1e61.5f80,56,,2012-02-01 21:25:53 PST,1/0,0,LOG,00000,"restored log file ""0000000100000DB400000066"" from archive",,,,,,,,,""
>
> All of these are on _vm relations. The recovery completed successfully and the secondary connected to the primary without issue, so: Are these messages something to be concerned over?

Hmm, I think I see how that can happen:

0. A heap page has its bit set in visibility map to begin with

1. A heap tuple is inserted/updated/deleted. This clears the VM bit.
2. time passes, and more WAL is generated
3. The page is vacuumed, and the visibility map bit is set again.

In the standby, this can happen while replaying the WAL, if you restart
the standby so that some WAL is re-replayed:

1. The update of the heap tuple is replayed. This clears the VM bit.
2. The VACUUM is replayed, setting the VM bit again, and updating the VM
page's LSN.
3. Shutdown and restart standby
4. The heap update is replayed again. This again clears the VM bit, but
does not set the LSN

If the VM page is now evicted from the buffer cache, you get the WARNING
you saw, because the page is dirty, yet its LSN is beyond the current
point in recovery.

AFAICS that's totally harmless, but the warning is quite alarming, so
we'll have to figure out a way to fix that. Not sure how; perhaps we
need to set the LSN on the VM page when the VM bit is cleared, but I
don't remember off the top of my head if there was some important reason
why we don't do that currently.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com