Re: Another possible corruption bug in 9.3.2 or possibly a known MultiXact problem?

Hi,

On 2014-02-24 17:55:14 -0300, Alvaro Herrera wrote:
> Greg Stark wrote:
> > I have a database where a a couple rows don't appear in index scans
> > but do appear in sequential scans. It looks like the same problem as
> > Peter reported but this is a different database. I've extracted all
> > the xlogdump records and below are the ones I think are relevant. You
> > can see that lp 2 gets a few HOT updates and concurrently has someone
> > create a MultiXact NO KEY UPDATE lock while one of those HOT updates
> > is pending but not committed.

Per se the sequence of records doesn't look bad (even though I am not
happy that we log intermediate and final rows first, and only then the
start of the chain).

> > The net result seems to be that the ctid
> > update chain got broken. The index of course points to the head of the
> > HOT chain so it doesn't find the live tail whereas the sequential scan
> > picks it up.

Yea, that's the problem.

> > rmgr: Heap len (rec/tot): 291/ 323, tx: 5943849, lsn: FD/2F0ADFC0, prev FD/2F0ADF90, bkp: 0000, desc: hot_update: rel 1663/16385/212653; tid 13065/2 xmax 5943849 ; new tid 13065/3 xmax 0
> > rmgr: Heap2 len (rec/tot): 25/ 57, tx: 5943851, lsn: FD/2F0AE450, prev FD/2F0AE408, bkp: 0000, desc: lock updated: xmax 5943851 msk 000a; rel 1663/16385/212653; tid 13065/3
> > rmgr: MultiXact len (rec/tot): 28/ 60, tx: 5943851, lsn: FD/2F0AE490, prev FD/2F0AE450, bkp: 0000, desc: create mxid 728896 offset 1632045 nmembers 2: 5943849 (nokeyupd) 5943851 (keysh)
> > rmgr: Heap len (rec/tot): 25/ 57, tx: 5943851, lsn: FD/2F0AE4D0, prev FD/2F0AE490, bkp: 0000, desc: lock 728896: rel 1663/16385/212653; tid 13065/2 IS_MULTI EXCL_LOCK

> > lp | lp_off | lp_flags | lp_len | t_xmin | t_xmax | t_field3 | t_ctid | t_infomask2 | t_infomask | t_hoff |
> > ----+--------+----------+--------+---------+---------+----------+------------+-------------+------------+--------+-
> > 2 | 3424 | 1 | 232 | 5943845 | 728896 | 0 | (13065,2) | 32 | 4419 | 32 |
> > 3 | 3152 | 1 | 272 | 5943849 | 5943879 | 0 | (13065,4) | 49184 | 9475 | 32 |
> > 4 | 2864 | 1 | 287 | 5943879 | 5943880 | 0 | (13065,7) | 49184 | 9475 | 32 |
> > 7 | 2576 | 1 | 287 | 5943880 | 0 | 0 | (13065,7) | 32800 | 10499 | 32 |

Those together explain the story. Note this bit:

static void
heap_xlog_lock(XLogRecPtr lsn, XLogRecord *record)
{
...
HeapTupleHeaderClearHotUpdated(htup);
HeapTupleHeaderSetXmax(htup, xlrec->locking_xid);
HeapTupleHeaderSetCmax(htup, FirstCommandId, false);
/* Make sure there is no forward chain link in t_ctid */
htup->t_ctid = xlrec->target.tid;
...
}

So, the replay of FD/2F0AE4D0 breaks the ctid chain *and* unsets the
HOT_UPDATED flag.

Which means fkey locks have never properly worked across SR/crash
recovery.

Haven't thought about how to fix it yet, I hope won't have to (hint hint).

We somehow need to have a policy of testing changes to the WAL format
without full_page_writes. They hide bugs in replay far, far too often.

Greetings,

Andres Freund

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