Re: Bug in visibility map WAL-logging

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?