Thread: ERROR: MultiXactId xxxx has not been created yet -- apparent wraparound

With PostgreSQL 9.3.5 on Ubuntu 12.04, I'm getting the error:

ERROR:  MultiXactId 1934308693 has not been created yet -- apparent 
wraparound

on doing various queries on our database. I don't think it is a 
wraparound - I think the tuple has mistakenly decided it has a 
MultiXactId related to it.

Looking back through the logs, it looks as if this suddenly started 
happening at 2:00 (UTC+0100) on 23 May. (Nothing was happening at that 
time as far as we can tell - the server didn't crash/restart or anything).

The logs were all really small, until the ones from then onwards, which 
are now full of things like:

2015-05-23 10:44:54 BST ERROR:  MultiXactId 1129406840 has not been 
created yet -- apparent wraparound
2015-05-23 10:44:54 BST CONTEXT:  automatic analyze of table 
"xxxxx.messages.msgdata"
2015-05-23 10:45:16 BST ERROR:  MultiXactId 1575170 has not been created 
yet -- apparent wraparound
2015-05-23 10:45:16 BST STATEMENT:  select sum(size) from messages.msgdata
2015-05-23 10:45:54 BST ERROR:  MultiXactId 1129406840 has not been 
created yet -- apparent wraparound
2015-05-23 10:45:54 BST CONTEXT:  automatic analyze of table 
"xxxxx.messages.msgdata"
2015-05-23 10:46:54 BST ERROR:  MultiXactId 1129406840 has not been 
created yet -- apparent wraparound

(There are several incorrect MultiXactIds in there).

This was NOT an upgrade. It has been running with 9.3 for ages.

The pg_controldata output is:

pg_control version number:            937
Catalog version number:               201306121
Database system identifier:           5990773948116871611
Database cluster state:               in production
pg_control last modified:             Tue 26 May 2015 09:50:25 BST
Latest checkpoint location:           7C6/8F863440
Prior checkpoint location:            7C6/8E8576D8
Latest checkpoint's REDO location:    7C6/8E8745F8
Latest checkpoint's REDO WAL file:    00000001000007C60000008E
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0/24005839
Latest checkpoint's NextOID:          1802564
Latest checkpoint's NextMultiXactId:  216
Latest checkpoint's NextMultiOffset:  439
Latest checkpoint's oldestXID:        710
Latest checkpoint's oldestXID's DB:   1
Latest checkpoint's oldestActiveXID:  0
Latest checkpoint's oldestMultiXid:   1
Latest checkpoint's oldestMulti's DB: 1
Time of latest checkpoint:            Tue 26 May 2015 09:45:57 BST
Fake LSN counter for unlogged rels:   0/1
Minimum recovery ending location:     0/0
Min recovery ending loc's timeline:   0
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
Current wal_level setting:            minimal
Current max_connections setting:      200
Current max_prepared_xacts setting:   0
Current max_locks_per_xact setting:   64
Maximum data alignment:               8
Database block size:                  8192
Blocks per segment of large relation: 131072
WAL block size:                       8192
Bytes per WAL segment:                16777216
Maximum length of identifiers:        64
Maximum columns in an index:          32
Maximum size of a TOAST chunk:        1996
Date/time type storage:               64-bit integers
Float4 argument passing:              by value
Float8 argument passing:              by value
Data page checksum version:           0

The pg_multixact directory contains two files
members/0000
offsets/0000

There are no locked up transactions is pg_stat_activity;

Any ideas? I can't even delete the records with the bad multixactid in 
them (which would be acceptable, as we can recover those individual 
records from backup). We don't want to restore fully from backup if 
possible as that will lose everything since the last good backup.



It was fixed in 9.3.7.

Unfortunately 9.3.7 has new bug which is irrelevant to this.
http://www.postgresql.org/message-id/20150525142657.4686.35151@wrigleys.postgresql.org

I'm not sure if Ubuntu 12.04 is affected by the bug or not though.

As far as I know developers plan to release 9.3.8 etc. soon.

Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp

> With PostgreSQL 9.3.5 on Ubuntu 12.04, I'm getting the error:
> 
> ERROR: MultiXactId 1934308693 has not been created yet -- apparent
> wraparound
> 
> on doing various queries on our database. I don't think it is a
> wraparound - I think the tuple has mistakenly decided it has a
> MultiXactId related to it.
> 
> Looking back through the logs, it looks as if this suddenly started
> happening at 2:00 (UTC+0100) on 23 May. (Nothing was happening at that
> time as far as we can tell - the server didn't crash/restart or
> anything).
> 
> The logs were all really small, until the ones from then onwards,
> which are now full of things like:
> 
> 2015-05-23 10:44:54 BST ERROR: MultiXactId 1129406840 has not been
> created yet -- apparent wraparound
> 2015-05-23 10:44:54 BST CONTEXT: automatic analyze of table
> "xxxxx.messages.msgdata"
> 2015-05-23 10:45:16 BST ERROR: MultiXactId 1575170 has not been
> created yet -- apparent wraparound
> 2015-05-23 10:45:16 BST STATEMENT: select sum(size) from
> messages.msgdata
> 2015-05-23 10:45:54 BST ERROR: MultiXactId 1129406840 has not been
> created yet -- apparent wraparound
> 2015-05-23 10:45:54 BST CONTEXT: automatic analyze of table
> "xxxxx.messages.msgdata"
> 2015-05-23 10:46:54 BST ERROR: MultiXactId 1129406840 has not been
> created yet -- apparent wraparound
> 
> (There are several incorrect MultiXactIds in there).
> 
> This was NOT an upgrade. It has been running with 9.3 for ages.
> 
> The pg_controldata output is:
> 
> pg_control version number:            937
> Catalog version number:               201306121
> Database system identifier:           5990773948116871611
> Database cluster state:               in production
> pg_control last modified:             Tue 26 May 2015 09:50:25 BST
> Latest checkpoint location:           7C6/8F863440
> Prior checkpoint location:            7C6/8E8576D8
> Latest checkpoint's REDO location:    7C6/8E8745F8
> Latest checkpoint's REDO WAL file:    00000001000007C60000008E
> Latest checkpoint's TimeLineID:       1
> Latest checkpoint's PrevTimeLineID:   1
> Latest checkpoint's full_page_writes: on
> Latest checkpoint's NextXID:          0/24005839
> Latest checkpoint's NextOID:          1802564
> Latest checkpoint's NextMultiXactId:  216
> Latest checkpoint's NextMultiOffset:  439
> Latest checkpoint's oldestXID:        710
> Latest checkpoint's oldestXID's DB:   1
> Latest checkpoint's oldestActiveXID:  0
> Latest checkpoint's oldestMultiXid:   1
> Latest checkpoint's oldestMulti's DB: 1
> Time of latest checkpoint:            Tue 26 May 2015 09:45:57 BST
> Fake LSN counter for unlogged rels:   0/1
> Minimum recovery ending location:     0/0
> Min recovery ending loc's timeline:   0
> Backup start location:                0/0
> Backup end location:                  0/0
> End-of-backup record required:        no
> Current wal_level setting:            minimal
> Current max_connections setting:      200
> Current max_prepared_xacts setting:   0
> Current max_locks_per_xact setting:   64
> Maximum data alignment:               8
> Database block size:                  8192
> Blocks per segment of large relation: 131072
> WAL block size:                       8192
> Bytes per WAL segment:                16777216
> Maximum length of identifiers:        64
> Maximum columns in an index:          32
> Maximum size of a TOAST chunk:        1996
> Date/time type storage:               64-bit integers
> Float4 argument passing:              by value
> Float8 argument passing:              by value
> Data page checksum version:           0
> 
> The pg_multixact directory contains two files
> members/0000
> offsets/0000
> 
> There are no locked up transactions is pg_stat_activity;
> 
> Any ideas? I can't even delete the records with the bad multixactid in
> them (which would be acceptable, as we can recover those individual
> records from backup). We don't want to restore fully from backup if
> possible as that will lose everything since the last good backup.
> 
> 
> 
> -- 
> Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-hackers




On 26/05/2015 10:23, Tatsuo Ishii wrote:
> It was fixed in 9.3.7.

OK.

Do you know what the bug number was or what it was called (I've tried 
searching for it before posting, but found nothing which seemed to be 
the same problem as ours).

Do you know whether, if we upgrade to 9.3.7/8, it will fix the problem 
in the current database, or is the data damage 'permanent', so we'll 
need to restore from backup and somehow merge in the latest data?





Re: ERROR: MultiXactId xxxx has not been created yet -- apparent wraparound

From
Alvaro Herrera
Date:
Paul Smith wrote:
> With PostgreSQL 9.3.5 on Ubuntu 12.04, I'm getting the error:
> 
> ERROR:  MultiXactId 1934308693 has not been created yet -- apparent
> wraparound
> 
> on doing various queries on our database. I don't think it is a wraparound -
> I think the tuple has mistakenly decided it has a MultiXactId related to it.

Yeah, that looks like the case.  According to your pg_controldata
output, you haven't used many multixacts at all:

> Latest checkpoint's NextMultiXactId:  216
> Latest checkpoint's NextMultiOffset:  439

and the fact that you only have these files:

> The pg_multixact directory contains two files
> members/0000
> offsets/0000

confirms this.  You XID counter is also rather low, only 24 million:

> Latest checkpoint's NextXID:          0/24005839

so it doesn't seem plausible that the single bit HEAP_XMAX_IS_MULTI was
turned on accidentally (something which I've never seen happen).

It doesn't look like a randomly corrupt page either; normally you would
see errors about mismatching page headers before you get to the point
where Xmax is read.  I wonder if the data page came from elsewhere.
Maybe you copied a data file from another database?

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services




On 26/05/2015 16:01, Alvaro Herrera wrote:
> Paul Smith wrote:
>> With PostgreSQL 9.3.5 on Ubuntu 12.04, I'm getting the error:
>>
>> ERROR:  MultiXactId 1934308693 has not been created yet -- apparent
>> wraparound
>>
>> on doing various queries on our database. I don't think it is a wraparound -
>> I think the tuple has mistakenly decided it has a MultiXactId related to it.
> Yeah, that looks like the case.  According to your pg_controldata
> output, you haven't used many multixacts at all:
Yep, that's what I thought as well.

> so it doesn't seem plausible that the single bit HEAP_XMAX_IS_MULTI 
> was turned on accidentally (something which I've never seen happen). 
> It doesn't look like a randomly corrupt page either; normally you 
> would see errors about mismatching page headers before you get to the 
> point where Xmax is read. I wonder if the data page came from 
> elsewhere. Maybe you copied a data file from another database? 

No, nothing like that. It was just running fine, and then suddenly (at 
2am on 23 May) it started throwing up loads of these errors. The DB 
server wasn't even restarted at that point. It was just working fine, 
then suddenly wasn't. (The first error was at 02:00:32 BST, then every 
few minutes after that there's another one).

It's running in a Hyper-V guest. We had taken a backup of the VM at 
00:34 on 23 May and that looks to be absolutely fine. What I have done 
now is restore that backup and import the new data which arrived since 
that backup was made, and it seems OK now. I still have the 'broken' 
installation in case more information is needed from it. I'd try to get 
a raw dump of the damaged tuple data if I knew how to find where it is 
in the relation file...

I suppose it's possible that it was disk or memory corruption, but I've 
seen that before, and it hasn't looked like this. (There are several 
PostgreSQL guests running on the same Hyper-V server, and none of the 
others seem to have this problem which may suggest that it's less likely 
to be a hardware issue).





Re: ERROR: MultiXactId xxxx has not been created yet -- apparent wraparound

From
Alvaro Herrera
Date:
Paul Smith wrote:

> No, nothing like that. It was just running fine, and then suddenly (at 2am
> on 23 May) it started throwing up loads of these errors. The DB server
> wasn't even restarted at that point. It was just working fine, then suddenly
> wasn't. (The first error was at 02:00:32 BST, then every few minutes after
> that there's another one).

Another crazy thought is that the host system messed up and overwrote
part of the table with pages from some other guest system.  I have never
seen a report of such a thing happening.

> It's running in a Hyper-V guest. We had taken a backup of the VM at 00:34 on
> 23 May and that looks to be absolutely fine. What I have done now is restore
> that backup and import the new data which arrived since that backup was
> made, and it seems OK now. I still have the 'broken' installation in case
> more information is needed from it. I'd try to get a raw dump of the damaged
> tuple data if I knew how to find where it is in the relation file...

Well, you could try a binary search to locate the (or a) borked page
within the table.  Or you could write a plpgsql function with an
EXCEPTION block that reads each tuple, and in case of error reports the
CTID of the tuple being read. (select * from tab where
ctid=generated_ctid; EXCEPT WHEN OTHERS THEN raise notice ' .. ',
generated_ctid).  Once you have located the problem tuple, a pageinspect
dump would be the starting point.

Another idea is to attach a debugger to the backend process, and set a
breakpoint on function errfinish.  Once the error is hit the breakpoint
will stop the execution before the error is reported; at that point you
can request for a backtrace from the debugger.  (Make sure to examine
errordata to see whether the error being hit is the multixact one.)

> I suppose it's possible that it was disk or memory corruption, but I've seen
> that before, and it hasn't looked like this.

Yeah, same here.

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services



On 05/26/2015 11:47 AM, Alvaro Herrera wrote:
> Paul Smith wrote:
> 
>> No, nothing like that. It was just running fine, and then suddenly (at 2am
>> on 23 May) it started throwing up loads of these errors. The DB server
>> wasn't even restarted at that point. It was just working fine, then suddenly
>> wasn't. (The first error was at 02:00:32 BST, then every few minutes after
>> that there's another one).
> 
> Another crazy thought is that the host system messed up and overwrote
> part of the table with pages from some other guest system.  I have never
> seen a report of such a thing happening.

I have.  Linux kernel version of the host?

-- 
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com



On 26/05/2015 19:47, Alvaro Herrera wrote:
> Paul Smith wrote:
>
>> No, nothing like that. It was just running fine, and then suddenly (at 2am
>> on 23 May) it started throwing up loads of these errors. The DB server
>> wasn't even restarted at that point. It was just working fine, then suddenly
>> wasn't. (The first error was at 02:00:32 BST, then every few minutes after
>> that there's another one).
> Another crazy thought is that the host system messed up and overwrote
> part of the table with pages from some other guest system.  I have never
> seen a report of such a thing happening.
Yes, that seems unlikely to me, but you never know...

While I was trying to work out how to fix it (after my original email), 
I did see a pgsql server crash:

2015-05-26 12:26:30 BST LOG:  server process (PID 35493) was terminated 
by signal 11: Segmentation fault

>
>> It's running in a Hyper-V guest. We had taken a backup of the VM at 00:34 on
>> 23 May and that looks to be absolutely fine. What I have done now is restore
>> that backup and import the new data which arrived since that backup was
>> made, and it seems OK now. I still have the 'broken' installation in case
>> more information is needed from it. I'd try to get a raw dump of the damaged
>> tuple data if I knew how to find where it is in the relation file...
> Well, you could try a binary search to locate the (or a) borked page
> within the table.  Or you could write a plpgsql function with an
> EXCEPTION block that reads each tuple, and in case of error reports the
> CTID of the tuple being read. (select * from tab where
> ctid=generated_ctid; EXCEPT WHEN OTHERS THEN raise notice ' .. ',
> generated_ctid).

In the backup, for the row which will become broken, I get:
    ctid    |   xmin   |   xmax
------------+----------+---------- (18722,29) | 23862661 | 23862661


Assuming it hadn't changed in the broken version (from application 
knowledge, it's unlikely to change), then on the broken version,
select heap_page_items(get_raw_page('messages.msgdata', 18722)); gives:
 (1,2,2,0,,,,,,,,,) (2,7816,1,376,21857691,21857691,11,"(18722,2)",32784,10646,24,,) (3,4,2,0,,,,,,,,,)
(4,7568,1,248,21858126,21858126,11,"(18722,4)",32784,10646,24,,)(5,6,2,0,,,,,,,,,)
(6,7216,1,352,22823803,23871405,41,"(18722,30)",49168,9478,24,,)(7,8,2,0,,,,,,,,,)
(8,6968,1,248,22825206,22825206,11,"(18722,8)",32784,10646,24,,)(9,10,2,0,,,,,,,,,)
(10,6720,1,248,22826427,22826427,11,"(18722,10)",32784,10646,24,,)(11,12,2,0,,,,,,,,,)
(12,6336,1,380,22826899,23935627,1,"(18722,31)",49168,9478,24,,)(13,0,3,0,,,,,,,,,) (14,15,2,0,,,,,,,,,)
(15,5400,1,932,23862314,23862314,11,"(18722,15)",32784,10642,24,,)(16,17,2,0,,,,,,,,,)
(17,5168,1,228,23862333,23862333,11,"(18722,17)",32784,10646,24,,)(18,19,2,0,,,,,,,,,)
(19,4800,1,368,23862365,23862365,11,"(18722,19)",32784,10646,24,,)(20,24,2,0,,,,,,,,,)
(21,3112,1,812,1332175474,894779760,223823413,"(1443526721,25142)",12141,18516,57,,)(22,23,2,0,,,,,,,,,)
(23,4448,1,352,728903474,1466642284,1869042033,"(1262568257,16743)",16751,26455,65,111101101000001011010010100000101010001011110110100000101101001010000010100000000000000000000000000000001010000001110110110000001000000001001000101000010110111000000000000000001100000111100010000000000000000010110010101100101101100000000000110010110010110011000000000000000000000000000000000000000000000000000000000000000000000010100001,)
(24,4184,1,264,619804,228,8000,"(956969542,26694)",22857,29251,98,110001101100001001100110011001100001110010000010001000100000111011110100110100101001011000101100100101100110001001000010101011100101111001010110111100101100001011000110101000101101011000011100010101100100110010011100110100101001101001100110110001101000101000110110100101100100001010011110000010100011011001000010101011001111001010100110010010100111011000101110010010101111010000011010110101101000001000101100101100101000101000001110000110101110001000001100110001100001001001010010000010100101001000011110010010100110110010000110101100000101000011100110110010100011011010110110100110101111010000100110,)
(25,26,2,0,,,,,,,,,)
(26,3928,1,252,1212837441,1232350037,1668772674,"(728910135,11093)",31284,16687,70,1111011010100010100010100100110011001100100000101101001001110110000101101110011001100110101101101001110010011110010010101000110011110100000100100010111011010100011010100001001010110110101100100011001000101010111011000000111011110100110011001011000001010000101101101111010010110110100001101000001010100010011011100100101010110110001100100101011001001110001101101100011001100110,1717791858)
(27,21,2,0,,,,,,,,,)(28,29,2,0,,,,,,,,,)
(29,2296,1,812,1229271346,1934308693,1733443957,"(1848337707,21358)",31337,21592,88,,1178686785)
(30,1944,1,352,947155032,1380218998,792031842,"(1211650927,22579)",30585,20532,80,,)
(31,1560,1,380,23935627,23935627,1,"(18722,31)",40976,9510,24,,)
(31 rows)


The data for index 29 has 1934308693 in the header (which is the 
multixactid reported in the error message when trying to retrieve that row).

I'm struggling to find the definitions for the data returned by 
heap_page_items, but the output from this page (for indexes between 21 
and 30) looks quite different from other neighbouring pages.

If I look at the raw page data, it contains data relating to this 
installation, so it doesn't look like a page from a different Hyper-V 
guest. It also doesn't look like just random data from a memory error. 
It actually looks like legitimate data which should possibly have been 
written elsewhere. (I don't want to post it here because it contains 
possibly confidential data from one of our customers).





Re: ERROR: MultiXactId xxxx has not been created yet -- apparent wraparound

From
Alvaro Herrera
Date:
Paul Smith wrote:

> In the backup, for the row which will become broken, I get:
> 
>     ctid    |   xmin   |   xmax
> ------------+----------+----------
>  (18722,29) | 23862661 | 23862661

Okay.

> Assuming it hadn't changed in the broken version (from application
> knowledge, it's unlikely to change), then on the broken version,
> select heap_page_items(get_raw_page('messages.msgdata', 18722)); gives:
> 
>  (21,3112,1,812,1332175474,894779760,223823413,"(1443526721,25142)",12141,18516,57,,)
>
(23,4448,1,352,728903474,1466642284,1869042033,"(1262568257,16743)",16751,26455,65,111101101000001011010010100000101010001011110110100000101101001010000010100000000000000000000000000000001010000001110110110000001000000001001000101000010110111000000000000000001100000111100010000000000000000010110010101100101101100000000000110010110010110011000000000000000000000000000000000000000000000000000000000000000000000010100001,)
>
(24,4184,1,264,619804,228,8000,"(956969542,26694)",22857,29251,98,110001101100001001100110011001100001110010000010001000100000111011110100110100101001011000101100100101100110001001000010101011100101111001010110111100101100001011000110101000101101011000011100010101100100110010011100110100101001101001100110110001101000101000110110100101100100001010011110000010100011011001000010101011001111001010100110010010100111011000101110010010101111010000011010110101101000001000101100101100101000101000001110000110101110001000001100110001100001001001010010000010100101001000011110010010100110110010000110101100000101000011100110110010100011011010110110100110101111010000100110,)
>
(26,3928,1,252,1212837441,1232350037,1668772674,"(728910135,11093)",31284,16687,70,1111011010100010100010100100110011001100100000101101001001110110000101101110011001100110101101101001110010011110010010101000110011110100000100100010111011010100011010100001001010110110101100100011001000101010111011000000111011110100110011001011000001010000101101101111010010110110100001101000001010100010011011100100101010110110001100100101011001001110001101101100011001100110,1717791858)
>  (29,2296,1,812,1229271346,1934308693,1733443957,"(1848337707,21358)",31337,21592,88,,1178686785)
>  (30,1944,1,352,947155032,1380218998,792031842,"(1211650927,22579)",30585,20532,80,,)
>  (31,1560,1,380,23935627,23935627,1,"(18722,31)",40976,9510,24,,)
> (31 rows)
> 
> 
> The data for index 29 has 1934308693 in the header (which is the multixactid
> reported in the error message when trying to retrieve that row).

Right.  The ctids on items 21, 23, 24, 26,29 and 30 are pretty obviously
corrupted (page numbers are too large, and offset numbers are way above
normal offset numbers), as is probaly everything else about them.  Note
xmin should be a valid xid, but for example on item 21 it's 133 million
which obviously is not a valid xid on your system.  Items 26 and 29 even
have an OID, which the others do not (indicating wrong HEAP_HASOID
flag).

Note the lp_off fields.  It seems that all valid items have offsets
above 4096, and corrupted items have offsets below that.  The theory
that somehow the system wrote a bad filesystem page (4096 bytes) on the
lower half of the Postgres page (8192 bytes) sounds rather more probable
now.

> I'm struggling to find the definitions for the data returned by
> heap_page_items,

Try \df+ heap_page_items; or more easily, use this query instead:
select * from heap_page_items(get_raw_page('messages.msgdata', 18722)); gives:

> If I look at the raw page data, it contains data relating to this
> installation, so it doesn't look like a page from a different Hyper-V guest.
> It also doesn't look like just random data from a memory error. It actually
> looks like legitimate data which should possibly have been written
> elsewhere. (I don't want to post it here because it contains possibly
> confidential data from one of our customers).

Sure.

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services