Re: BUG #14195: "MultiXactId XXXXXX has not been created yet -- apparent wraparound" after upgrade from 9.2

>>>>> "sean" == sean hope <sean(dot)hope(at)eroad(dot)com> writes:

sean> The following bug has been logged on the website:
sean> Bug reference: 14195
sean> Logged by: Sean Hope
sean> Email address: sean(dot)hope(at)eroad(dot)com
sean> PostgreSQL version: 9.4.7
sean> Operating system: Ubuntu 12.04 LTS
sean> Description:

sean> Hi,

sean> We're having issues with 'MultiXactId xxxxxxxxx has not been
sean> created yet -- apparent wraparound' log messages upon table
sean> vacuums. The vacuums are cancelled by the system after this
sean> message is issued.

sean> These messages have only been seen since upgrading from 9.2.x to
sean> 9.4.7 via pg_upgrade about a month ago. This is a large / high
sean> transaction rate (1120 tps) database. We are unable to vacuum the
sean> affected tables (5 of them) currently due to this issue.

This one came up on the IRC channel and I did some analysis there.

What it seems to boil down to is that, faced with a tuple with a
pre-upgrade mxid, we get this call path:

vacuum calls heap_prepare_freeze_tuple

heap_prepare_freeze_tuple calls FreezeMultiXactId
(because HEAP_XMAX_IS_MULTI)

FreezeMultiXactId checks if the mxid is older than the cutoff, but
because this is a pre-upgrade mxid it can be literally anything, and in
this case it's in the future not the past, so that check is skipped

FreezeMultiXactId calls GetMultiXactIdMembers with allow_old=true

GetMultiXactIdMembers checks for wraparound, but while it downgrades the
error to DEBUG1 if allow_old is true and the mxid is in the past, it
unconditionally errors if the mxid is in the future.

From pageinspect output this is one of the failing tuples:

blk: 291;
lp: 35;
lp_off: 7992;
lp_flags: 1;
lp_len: 196;
t_xmin: 2;
t_xmax: 197529992;
t_field3: 21;
t_ctid: (291,35);
t_infomask2: 32791;
t_infomask: 14723; (0x3983)
t_hoff: 32;
bits: "111111111111111111111100000000000000000000000000000000000000000000000000";

(note: the pageinspect output was all absolutely consistent, there were
no signs of any data corruption of any kind)

from pg_controldata:

Latest checkpoint's NextMultiXactId: 3125330305
Latest checkpoint's NextMultiOffset: 2217410182
Latest checkpoint's oldestMultiXid: 2741572175

--
Andrew (irc:RhodiumToad)