Re: Bug in visibility map WAL-logging

Поиск
Список
Период
Сортировка
От Matheus de Oliveira
Тема Re: Bug in visibility map WAL-logging
Дата
Msg-id CAJghg4Lvg_CEpJnM71qzb0-veKoFG-q_YQu==M_jr3YApHhi=w@mail.gmail.com
обсуждение исходный текст
Ответ на Bug in visibility map WAL-logging  (Heikki Linnakangas <hlinnakangas@vmware.com>)
Ответы Re: Bug in visibility map WAL-logging  (Heikki Linnakangas <hlinnakangas@vmware.com>)
Список pgsql-hackers
Дерево обсуждения
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

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
2088223 ... Heap2 ...  20/    52, ... lsn: 2BC/46AB8C98 ... desc: visible: rel 1663/883916/151040222; blk 1075
2088224 ... Heap2 ...  32/    64, ... lsn: 2BC/46AB8CD0 ... desc: clean: rel 1663/883916/151040222; blk 1075 remxid 107409880
== two lines that matched bellow ==
2088225 ... Heap2 ...  20/    52, ... lsn: 2BC/46AB8D10 ... desc: visible: rel 1663/883916/151040222; blk 1076
2088226 ... Heap2 ...  24/   164, ... lsn: 2BC/46AB8D48 ... desc: clean: rel 1663/883916/151040222; blk 1076 remxid 107409880
2088227 ... Heap2 ...  20/    52, ... lsn: 2BC/46AB8DF0 ... desc: visible: rel 1663/883916/151040222; blk 1077
2088228 ... Heap2 ...  24/   128, ... lsn: 2BC/46AB8E28 ... desc: clean: rel 1663/883916/151040222; blk 1077 remxid 107409880
2088229 ... Heap2 ...  20/    52, ... lsn: 2BC/46AB8EA8 ... desc: visible: rel 1663/883916/151040222; blk 1078
2088230 ... Heap2 ...  24/  5748, ... lsn: 2BC/46AB8EE0 ... desc: clean: rel 1663/883916/151040222; blk 1078 remxid 107409880
2088231 ... Heap2 ...  20/    52, ... lsn: 2BC/46ABA570 ... desc: visible: rel 1663/883916/151040222; blk 1079


I cropped some columns to make it easy to read (the entire result is attached), if you guys need more information, I can send the xlogdump of all the WALs (or any other information). Also attached the controldata, if needed.


Thanks a lot.

Best regards,
--
Matheus de Oliveira
Analista de Banco de Dados
Dextra Sistemas - MPS.Br nível F!
www.dextra.com.br/postgres

Вложения

В списке pgsql-hackers по дате отправления:

Предыдущее
От: Magnus Hagander
Дата:
Сообщение: Re: Assertion failure in base backup code path
Следующее
От: Emre Hasegeli
Дата:
Сообщение: Failed assertion root->hasLateralRTEs on initsplan.c