Thread: Bug in visibility map WAL-logging

lazy_vacuum_page() does this:

1. START_CRIT_SECTION()
2. Remove dead tuples from the page, marking the itemid's unused.
3. MarkBufferDirty
4. if all remaining tuples on the page are visible to everyone, set the 
all-visible flag on the page, and call visibilitymap_set() to set the VM 
bit.
5 visibilitymap_set() writes a WAL record about setting the bit in the 
visibility map.
6. write the WAL record of removing the dead tuples.
7. END_CRIT_SECTION().

See the problem? Setting the VM bit is WAL-logged first, before the 
removal of the tuples. If you stop recovery between the two WAL records, 
the page's VM bit in the VM map will be set, but the dead tuples are 
still on the page.

This bug was introduced in Feb 2013, by commit 
fdf9e21196a6f58c6021c967dc5776a16190f295, so it's present in 9.3 and master.

The fix seems quite straightforward, we just have to change the order of 
those two records. I'll go commit that.

- Heikki

On 01/07/2014 07:15 PM, Matheus de Oliveira wrote:
> Hi folks,
>
>
> On Fri, Dec 13, 2013 at 9:47 AM, Heikki Linnakangas <hlinnakangas@vmware.com
>> wrote:
>
>> lazy_vacuum_page() does this:
>>
>> 1. START_CRIT_SECTION()
>> 2. Remove dead tuples from the page, marking the itemid's unused.
>> 3. MarkBufferDirty
>> 4. if all remaining tuples on the page are visible to everyone, set the
>> all-visible flag on the page, and call visibilitymap_set() to set the VM
>> bit.
>> 5 visibilitymap_set() writes a WAL record about setting the bit in the
>> visibility map.
>> 6. write the WAL record of removing the dead tuples.
>> 7. END_CRIT_SECTION().
>>
>> See the problem? Setting the VM bit is WAL-logged first, before the
>> removal of the tuples. If you stop recovery between the two WAL records,
>> the page's VM bit in the VM map will be set, but the dead tuples are still
>> on the page.
>>
>> This bug was introduced in Feb 2013, by commit
>> fdf9e21196a6f58c6021c967dc5776a16190f295, so it's present in 9.3 and master.
>>
>> The fix seems quite straightforward, we just have to change the order of
>> those two records. I'll go commit that.
>>
>
>
> With a lot of help from Andres on IRC (thanks a lot man), I think (he
> thinks actually, =P ) I may ran into the issue this bug can cause. I'm
> sending this e-mail to (1) confirm if my issue is really caused by that bug
> and if that is the case, (2) let you guys know the problems it can cause.
>
> Scenario:
>
> Master: 9.3.1 (I know, trying to go to 9.3.2)
> Slave: 9.3.2
>
> The slave was running with hot_standby=off (because of other bug Andres is
> working on), but it stopped working with the following log lines:
>
> 2014-01-07 12:38:04 BRST [22668]: [7-1] user=,db= WARNING:  page 1076 of
> relation base/883916/151040222 is uninitialized
> 2014-01-07 12:38:04 BRST [22668]: [8-1] user=,db= CONTEXT:  xlog redo
> visible: rel 1663/883916/151040222; blk 1076
> 2014-01-07 12:38:04 BRST [22668]: [9-1] user=,db= PANIC:  WAL contains
> references to invalid pages
> 2014-01-07 12:38:04 BRST [22668]: [10-1] user=,db= CONTEXT:  xlog redo
> visible: rel 1663/883916/151040222; blk 1076
> 2014-01-07 12:38:04 BRST [22665]: [3-1] user=,db= LOG:  startup process
> (PID 22668) was terminated by signal 6: Aborted
>
> (Complete log at https://pgsql.privatepaste.com/343f3190fe).
>
> I used pg_xlogdump to (try to) find the block the error relates to:
>
> $ pg_xlogdump pg_xlog/00000001000002BC0000002B 00000001000002BC0000007F |
> grep -n -C5 '883916/151040222; blk 1076'
>
> 2088220 ... Heap2 ...  24/   192, ... lsn: 2BC/46AB8B20 ... desc: clean:
> rel 1663/883916/151040222; blk 1073 remxid 107409880
> 2088221 ... Heap2 ...  20/    52, ... lsn: 2BC/46AB8BE0 ... desc: visible:
> rel 1663/883916/151040222; blk 1074
> 2088222 ... Heap2 ...  24/   128, ... lsn: 2BC/46AB8C18 ... desc: clean:
> rel 1663/883916/151040222; blk 1074 remxid 107409880> ...

Hmm. The xlogdump indeed shows that the order of 'clean' and 'visible' 
is incorrect, but I don't immediately see how that could cause the 
PANIC. Why is the page uninitialized in the standby? If VACUUM is 
removing some dead tuples from it, it certainly should exist and be 
correctly initialized.

How did you set up the standby? Did you initialize it from an offline 
backup of the master's data directory, perhaps? The log shows that the 
startup took the the "crash recovery first, then start archive recovery" 
path, because there was no backup label file. In that mode, the standby 
assumes that the system is consistent after replaying all the WAL in 
pg_xlog, which is correct if you initialize from an offline backup or 
atomic filesystem snapshot, for example. But "WAL contains references to 
invalid pages" could also be a symptom of an inconsistent base backup, 
cause by incorrect backup procedure. In particular, I have to ask 
because I've seen it before: you didn't delete backup_label from the 
backup, did you?

- Heikki

On 2014-01-07 21:36:31 +0200, Heikki Linnakangas wrote:
> >2088220 ... Heap2 ...  24/   192, ... lsn: 2BC/46AB8B20 ... desc: clean:
> >rel 1663/883916/151040222; blk 1073 remxid 107409880
> >2088221 ... Heap2 ...  20/    52, ... lsn: 2BC/46AB8BE0 ... desc: visible:
> >rel 1663/883916/151040222; blk 1074
> >2088222 ... Heap2 ...  24/   128, ... lsn: 2BC/46AB8C18 ... desc: clean:
> >rel 1663/883916/151040222; blk 1074 remxid 107409880
> > ...
> 
> Hmm. The xlogdump indeed shows that the order of 'clean' and 'visi ble' is
> incorrect, but I don't immediately see how that could cause the PANIC. Why
> is the page uninitialized in the standby? If VACUUM is removing some dead
> tuples from it, it certainly should exist and be correctly initialized.

Yea, that's strange. I first thought it might be the PageIsNew() branch
in lazy_scan_heap(). That initializes the page without WAL logging which
would explain it being uninitialized on the standby. But that wouldn't
explain why we found something to clean on the primary while the page is
still empty on the standby...

> How did you set up the standby? Did you initialize it from an offline backup
> of the master's data directory, perhaps? The log shows that the startup took
> the the "crash recovery first, then start archive recovery" path, because
> there was no backup label file

Good point.

>In particular, I have to ask because I've seen it before: you
> didn't delete backup_label from the backup, did you?

I have seen that repeatedly too.

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

On Tue, Jan 7, 2014 at 11:36 AM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:
> Hmm. The xlogdump indeed shows that the order of 'clean' and 'visible' is
> incorrect, but I don't immediately see how that could cause the PANIC. Why
> is the page uninitialized in the standby? If VACUUM is removing some dead
> tuples from it, it certainly should exist and be correctly initialized.


Unless the vacuum subsequently truncated the file to be shorter and
the backup was taken after that?

-- 
greg

On 01/08/2014 02:32 PM, Matheus de Oliveira wrote:
> On Tue, Jan 7, 2014 at 10:42 PM, Matheus de Oliveira <
> matioli.matheus@gmail.com> wrote:
>
>> How did you set up the standby? Did you initialize it from an offline
>>> backup of the master's data directory, perhaps? The log shows that the
>>> startup took the the "crash recovery first, then start archive recovery"
>>> path, because there was no backup label file. In that mode, the standby
>>> assumes that the system is consistent after replaying all the WAL in
>>> pg_xlog, which is correct if you initialize from an offline backup or
>>> atomic filesystem snapshot, for example. But "WAL contains references to
>>> invalid pages" could also be a symptom of an inconsistent base backup,
>>> cause by incorrect backup procedure. In particular, I have to ask because
>>> I've seen it before: you didn't delete backup_label from the backup, did
>>> you?
>>
>> Well, I cannot answer this right now, but makes all sense and is possible.
>
> I've just confirmed. That was indeed the case, the script was removing the
> backup_label. I've just removed this line and synced it again, it is
> running nice (for past 1 hour at least).

A-ha! ;-)

> Thank you guys for all your help, and sorry for all the confusion I caused.

That seems to be a very common mistake to make. I wish we could do 
something about it. Do you think it would've helped in your case if 
there was a big fat warning in the beginning of backup_label, along the 
lines of: "# DO NOT REMOVE THIS FILE FROM A BACKUP" ? Any other ideas 
how we could've made it more obvious to the script author to not remove it?

- Heikki

On 2014-01-08 14:37:34 +0200, Heikki Linnakangas wrote:
> That seems to be a very common mistake to make. I wish we could do something
> about it. Do you think it would've helped in your case if there was a big
> fat warning in the beginning of backup_label, along the lines of: "# DO NOT
> REMOVE THIS FILE FROM A BACKUP" ? Any other ideas how we could've made it
> more obvious to the script author to not remove it?

I've been wondering about the possibility of setting a boolean in
checkpoint records indicating that a backup label needs to be used when
starting from that checkpoint. That boolean would only get checked when
using a recovery.conf and we've started with pg_control indicating that
it was written by a primary (i.e. state <= DB_SHUTDOWNING).

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

On 2014-01-07 22:42:59 -0200, Matheus de Oliveira wrote:
> @andres, if it is really removing backup_label it could also cause that
> other issue we saw on Monday, right? (yes I did run the same script).

It might be in your case since that's an easy to way to generate that
situation, but there have been several other reports of that bug, so
it's good that we've discussed it ;)

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

On 01/08/2014 07:29 AM, Greg Stark wrote:
> On Tue, Jan 7, 2014 at 11:36 AM, Heikki Linnakangas
> <hlinnakangas@vmware.com> wrote:
>> Hmm. The xlogdump indeed shows that the order of 'clean' and 'visible' is
>> incorrect, but I don't immediately see how that could cause the PANIC. Why
>> is the page uninitialized in the standby? If VACUUM is removing some dead
>> tuples from it, it certainly should exist and be correctly initialized.
>
> Unless the vacuum subsequently truncated the file to be shorter and
> the backup was taken after that?

In that case WAL replay should also see the truncation record before 
reaching consistency. We only PANIC on an uninitialized/missing page 
after reaching consistency, before that it's indeed normal if the file 
was later truncated or deleted.

- Heikki