ERROR: invalid memory alloc request size <a_big_number_here>

On Thu, Oct 27, 2005 at 10:59:30AM +0200, Matteo Beccati wrote:

Hi,

I'm using 8.1beta4 on a development server for a rather db-intensive
application. This application has a multiprocess daemon which was
working fairly well in past. After some recent changes I started having
deadlock problems. While investigating to remove what was causing them I
removed some FOR UPDATE clauses (added on 8.0 to prevent other deadlock
situations), hoping that the newly added FK share locks would better
handle the concurrent access. In fact the deadlock errors went away, but
I suddenly started getting some of these:

Backtrace would be nice. I don't suppose your backend is compiled with
debugging? If so, try attaching to the backend and do:

break MemoryContextAlloc if size > 1000000000

Obviously something is trying to allocate and negative number of
bytes... 4291419108 = -3548188

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Hi Martijn,

Backtrace would be nice. I don't suppose your backend is compiled with
debugging? If so, try attaching to the backend and do:

break MemoryContextAlloc if size > 1000000000

Obviously something is trying to allocate and negative number of
bytes... 4291419108 = -3548188

Here is the backtrace, hoping I did it correctly:

Breakpoint 1, Mem
oryContextAlloc (context=0xbfbfd5d0, size=3217020368) at mcxt.c:501
501 {
(gdb) bt
#0 MemoryContextAlloc (context=0xbfbfd5d0, size=3217020368) at mcxt.c:501
#1 0x0812a586 in initStringInfo (str=0xbfbfd5d0) at stringinfo.c:50
#2 0x081303e5 in pq_beginmessage (buf=0xbfbfd5d0, msgtype=84 'T') at
pqformat.c:92
#3 0x080778b5 in SendRowDescriptionMessage (typeinfo=0x8311420,
targetlist=0xbfbfd5d0, formats=0x83df088) at printtup.c:170
#4 0x08117200 in ExecutorRun (queryDesc=0x83df040,
direction=ForwardScanDirection, count=0) at execMain.c:222
#5 0x0818a16f in PortalRunSelect (portal=0x835f018, forward=32 ' ',
count=0, dest=0x83a7448) at pquery.c:794
#6 0x0818a60e in PortalRun (portal=0x835f018, count=2147483647,
dest=0x83a7448, altdest=0x83a7448, completionTag=0xbfbfd830 "") at
pquery.c:646
#7 0x081868cc in exec_simple_query (query_string=0x8310228 "SELECT *
FROM gw_queue_get('7')") at postgres.c:1014
#8 0x08188e4f in PostgresMain (argc=4, argv=0x82dd3d0,
username=0x82dd3a0 "multilevel") at postgres.c:3168
#9 0x08165dbc in ServerLoop () at postmaster.c:2853
#10 0x081672bd in PostmasterMain (argc=3, argv=0xbfbfed3c) at
postmaster.c:943
#11 0x08131092 in main (argc=3, argv=0xbfbfed3c) at main.c:256

Best regards
--
Matteo Beccati
http://phpadsnew.com
http://phppgads.com

On Thu, Oct 27, 2005 at 11:37:09AM +0200, Matteo Beccati wrote:

Here is the backtrace, hoping I did it correctly:

Dagnammit. I was wondering if that was going to happen. If your
optimisation is up, the values of arguments to the functions don't
display right (look at the rest, they're obviously not correct). While
it's possible there's a bug that early in the output, I wouldn't bet on
it.

The trick (other than turning off optimisation) is to set the
breakpoint a few lines later, like say mcxt.c:504. You can find out by
simply stepping the debugger until "p size" displays a reasonable
value.

try with: break mcxt.c:504 if size > 1000000000

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Belay that, you should be able to put a breakpoint on errstart or elog
or perhaps errmsg. Much easier...

(I expected the find the answer in the developer FAQ, but it's not
there).

Hope this helps,

On Thu, Oct 27, 2005 at 12:04:45PM +0200, Martijn van Oosterhout wrote:

On Thu, Oct 27, 2005 at 11:37:09AM +0200, Matteo Beccati wrote:

Here is the backtrace, hoping I did it correctly:

Dagnammit. I was wondering if that was going to happen. If your
optimisation is up, the values of arguments to the functions don't
display right (look at the rest, they're obviously not correct). While
it's possible there's a bug that early in the output, I wouldn't bet on
it.

The trick (other than turning off optimisation) is to set the
breakpoint a few lines later, like say mcxt.c:504. You can find out by
simply stepping the debugger until "p size" displays a reasonable
value.

try with: break mcxt.c:504 if size > 1000000000

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.

--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Martijn van Oosterhout wrote:
-- Start of PGP signed section.

Belay that, you should be able to put a breakpoint on errstart or elog
or perhaps errmsg. Much easier...

(I expected the find the answer in the developer FAQ, but it's not
there).

I removed it because it used to be in the main FAQ, and wasn't asked
"frequently". Should it be readded?

---------------------------------------------------------------------------

Hope this helps,

On Thu, Oct 27, 2005 at 12:04:45PM +0200, Martijn van Oosterhout wrote:

On Thu, Oct 27, 2005 at 11:37:09AM +0200, Matteo Beccati wrote:

Here is the backtrace, hoping I did it correctly:

Dagnammit. I was wondering if that was going to happen. If your
optimisation is up, the values of arguments to the functions don't
display right (look at the rest, they're obviously not correct). While
it's possible there's a bug that early in the output, I wouldn't bet on
it.

The trick (other than turning off optimisation) is to set the
breakpoint a few lines later, like say mcxt.c:504. You can find out by
simply stepping the debugger until "p size" displays a reasonable
value.

try with: break mcxt.c:504 if size > 1000000000

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.

--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.

-- End of PGP section, PGP failed!

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

On Thu, Oct 27, 2005 at 08:54:57AM -0400, Bruce Momjian wrote:

Martijn van Oosterhout wrote:
-- Start of PGP signed section.

Belay that, you should be able to put a breakpoint on errstart or elog
or perhaps errmsg. Much easier...

(I expected the find the answer in the developer FAQ, but it's not
there).

I removed it because it used to be in the main FAQ, and wasn't asked
"frequently". Should it be readded?

Hmm, depends. It's not asked often, that for sure. Yet everytime it
comes up I keep forgetting if I should be breaking on errstart, errmsg
or something else. One of these days I might just write it on a post-it
note next to my computer.

Maybe not as a seperate question, but in "2.8) What debugging features
are available?" add something like below. It'd be easier to point it
out to people on the web instead of saying it time.

- Additionally, if you get an unusual error message, it can be useful
- to get a stack trace to see how it got there. One trick is to attach
- gdb and tell it to break on elog and errstart/errmsg/errfinish
- (whichever is the right one) and you can get a stack trace at exactly
- the point it is dying. Note that DEBUG level message will trigger
- also so you might need to "cont" a few times to get the error you
- want.
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Martijn van Oosterhout wrote:

Belay that, you should be able to put a breakpoint on errstart or elog
or perhaps errmsg. Much easier...

After several tries, I finally found a way to produce a reliable
backtrace :)

Breakpoint 4, errfinish (dummy=0) at elog.c:346
346 ImmediateInterruptOK = false;
(gdb) bt
#0 errfinish (dummy=0) at elog.c:346
#1 0x08265896 in elog_finish (elevel=20, fmt=0x831858c "invalid memory
alloc request size %lu") at elog.c:930
#2 0x0827b5cf in MemoryContextAlloc (context=0x85b2238,
size=4279476584) at mcxt.c:505
#3 0x080b6a16 in GetMultiXactIdMembers (multi=301994, xids=0xbfbfaba4)
at multixact.c:935
#4 0x080b6271 in MultiXactIdIsRunning (multi=301994) at multixact.c:373
#5 0x0828347d in HeapTupleSatisfiesUpdate (tuple=0x28ccbb40, curcid=13,
buffer=756) at tqual.c:620
#6 0x0808f724 in heap_lock_tuple (relation=0x8402988, tuple=0xbfbfad10,
buffer=0xbfbfad0c, ctid=0xbfbfacf0, update_xmax=0xbfbfacec, cid=13,
mode=LockTupleShared, nowait=0 '\0') at heapam.c:2055
#7 0x0814153d in ExecutePlan (estate=0x8574018, planstate=0x8574198,
operation=CMD_SELECT, numberTuples=1, direction=ForwardScanDirection,
dest=0x831b978)
at execMain.c:1188
#8 0x081404fb in ExecutorRun (queryDesc=0x8571088,
direction=ForwardScanDirection, count=1) at execMain.c:230
#9 0x0815ad7e in _SPI_pquery (queryDesc=0x8571088, tcount=1) at spi.c:1558
#10 0x0815ab98 in _SPI_execute_plan (plan=0x8546c18, Values=0xbfbfaf70,
Nulls=0xbfbfaf30 " ", snapshot=0x0, crosscheck_snapshot=0x0, read_only=0
'\0',
tcount=1) at spi.c:1460
#11 0x08158b3c in SPI_execute_snapshot (plan=0x8546c18,
Values=0xbfbfaf70, Nulls=0xbfbfaf30 " ", snapshot=0x0,
crosscheck_snapshot=0x0, read_only=0 '\0',
tcount=1) at spi.c:379
#12 0x08248cd7 in ri_PerformCheck (qkey=0xbfbfcb80, qplan=0x8546c18,
fk_rel=0x84bdab0, pk_rel=0x8402988, old_tuple=0x0, new_tuple=0xbfbfcef0,
detectNewRows=0 '\0', expect_OK=5, constrname=0x8547448 "$2") at
ri_triggers.c:3141
#13 0x08244576 in RI_FKey_check (fcinfo=0xbfbfcc90) at ri_triggers.c:424
#14 0x082445e5 in RI_FKey_check_ins (fcinfo=0xbfbfcc90) at ri_triggers.c:449
#15 0x0812d2a5 in ExecCallTriggerFunc (trigdata=0xbfbfcf30, tgindx=2,
finfo=0x85475d8, instr=0x0, per_tuple_context=0x85b2568) at trigger.c:1288
#16 0x0812e349 in AfterTriggerExecute (event=0x84284e0, rel=0x84bdab0,
trigdesc=0x85470e8, finfo=0x85475a8, instr=0x0, per_tuple_context=0x85b2568)
at trigger.c:2134
#17 0x0812e6f7 in afterTriggerInvokeEvents (events=0x8428118,
firing_id=2, estate=0x8547018, delete_ok=1 '\001') at trigger.c:2376
#18 0x0812e993 in AfterTriggerEndQuery (estate=0x8547018) at trigger.c:2551
#19 0x0815adf9 in _SPI_pquery (queryDesc=0x8541088, tcount=0) at spi.c:1570
#20 0x0815ab98 in _SPI_execute_plan (plan=0x8531818, Values=0x85234a0,
Nulls=0x8523490 " �\024", snapshot=0x0, crosscheck_snapshot=0x0,
read_only=0 '\0',
tcount=0) at spi.c:1460
#21 0x08158a82 in SPI_execute_plan (plan=0x8531818, Values=0x85234a0,
Nulls=0x8523490 " �\024", read_only=0 '\0', tcount=0) at spi.c:336
#22 0x2dc470a6 in exec_stmt_execsql (estate=0xbfbfd330, stmt=0x85287c8)
at pl_exec.c:2280
#23 0x2dc45312 in exec_stmt (estate=0xbfbfd330, stmt=0x85287c8) at
pl_exec.c:1076
#24 0x2dc45115 in exec_stmts (estate=0xbfbfd330, stmts=0x8528738) at
pl_exec.c:991
#25 0x2dc455d5 in exec_stmt_if (estate=0xbfbfd330, stmt=0x852d828) at
pl_exec.c:1210
#26 0x2dc45218 in exec_stmt (estate=0xbfbfd330, stmt=0x852d828) at
pl_exec.c:1036
#27 0x2dc45115 in exec_stmts (estate=0xbfbfd330, stmts=0x852d860) at
pl_exec.c:991
#28 0x2dc44fbb in exec_stmt_block (estate=0xbfbfd330, block=0x852d8a0)
at pl_exec.c:936
#29 0x2dc446e1 in plpgsql_exec_trigger (func=0x8527018,
trigdata=0xbfbfd690) at pl_exec.c:562
#30 0x2dc3fcdf in plpgsql_call_handler (fcinfo=0xbfbfd3f0) at
pl_handler.c:120
#31 0x0812d2a5 in ExecCallTriggerFunc (trigdata=0xbfbfd690, tgindx=3,
finfo=0x84794d0, instr=0x0, per_tuple_context=0x854fa68) at trigger.c:1288
#32 0x0812e349 in AfterTriggerExecute (event=0x84283a8, rel=0x84969b0,
trigdesc=0x84790e8, finfo=0x8479488, instr=0x0, per_tuple_context=0x854fa68)
at trigger.c:2134
#33 0x0812e6f7 in afterTriggerInvokeEvents (events=0x8428110,
firing_id=0, estate=0x8479018, delete_ok=1 '\001') at trigger.c:2376
#34 0x0812e993 in AfterTriggerEndQuery (estate=0x8479018) at trigger.c:2551
#35 0x0815adf9 in _SPI_pquery (queryDesc=0x84640c8, tcount=0) at spi.c:1570
#36 0x0815ab98 in _SPI_execute_plan (plan=0x8467418, Values=0x843c248,
Nulls=0x843c238 " \024", snapshot=0x0, crosscheck_snapshot=0x0,
read_only=0 '\0',
tcount=0) at spi.c:1460
#37 0x08158a82 in SPI_execute_plan (plan=0x8467418, Values=0x843c248,
Nulls=0x843c238 " \024", read_only=0 '\0', tcount=0) at spi.c:336
#38 0x2dc470a6 in exec_stmt_execsql (estate=0xbfbfda40, stmt=0x8449088)
at pl_exec.c:2280
#39 0x2dc45312 in exec_stmt (estate=0xbfbfda40, stmt=0x8449088) at
pl_exec.c:1076
#40 0x2dc45115 in exec_stmts (estate=0xbfbfda40, stmts=0x8448e50) at
pl_exec.c:991
#41 0x2dc44fbb in exec_stmt_block (estate=0xbfbfda40, block=0x84492b0)
at pl_exec.c:936
#42 0x2dc43cda in plpgsql_exec_function (func=0x8448018,
fcinfo=0xbfbfdb30) at pl_exec.c:286
#43 0x2dc3fcf5 in plpgsql_call_handler (fcinfo=0xbfbfdb30) at
pl_handler.c:123
#44 0x081447e2 in ExecMakeFunctionResult (fcache=0x8436238,
econtext=0x84361b0, isNull=0x84367e8 "", isDone=0x8436840) at
execQual.c:1096
#45 0x08145060 in ExecEvalFunc (fcache=0x8436238, econtext=0x84361b0,
isNull=0x84367e8 "", isDone=0x8436840) at execQual.c:1498
#46 0x0814888a in ExecTargetList (targetlist=0x84366b8,
econtext=0x84361b0, values=0x84367d8, isnull=0x84367e8 "",
itemIsDone=0x8436840, isDone=0xbfbfde14)
at execQual.c:3670
---Type <return> to continue, or q <return> to quit---
#47 0x08148c7c in ExecProject (projInfo=0x84367f8, isDone=0xbfbfde14) at
execQual.c:3871
#48 0x081544cc in ExecResult (node=0x8436128) at nodeResult.c:157
#49 0x08142c9d in ExecProcNode (node=0x8436128) at execProcnode.c:306
#50 0x08141331 in ExecutePlan (estate=0x8436018, planstate=0x8436128,
operation=CMD_SELECT, numberTuples=0, direction=ForwardScanDirection,
dest=0x83d38e0)
at execMain.c:1102
#51 0x081404fb in ExecutorRun (queryDesc=0x8466c40,
direction=ForwardScanDirection, count=0) at execMain.c:230
#52 0x081de829 in PortalRunSelect (portal=0x842a018, forward=1 '\001',
count=0, dest=0x83d38e0) at pquery.c:794
#53 0x081de519 in PortalRun (portal=0x842a018, count=2147483647,
dest=0x83d38e0, altdest=0x83d38e0, completionTag=0xbfbfe080 "") at
pquery.c:611
#54 0x081da2a5 in exec_simple_query (query_string=0x83d3120 "SELECT
gw_queue_ok('1363827', 'OK 3000')") at postgres.c:1014
#55 0x081dd220 in PostgresMain (argc=4, argv=0x83643d0,
username=0x83643a0 "multilevel") at postgres.c:3168
#56 0x081b01ea in BackendRun (port=0x8361200) at postmaster.c:2855
#57 0x081af7d3 in BackendStartup (port=0x8361200) at postmaster.c:2498
#58 0x081ad86b in ServerLoop () at postmaster.c:1231
#59 0x081ad0eb in PostmasterMain (argc=3, argv=0xbfbfed3c) at
postmaster.c:943
#60 0x08163962 in main (argc=3, argv=0xbfbfed3c) at main.c:256

Best regards
--
Matteo Beccati
http://phpadsnew.com
http://phppgads.com

Martijn van Oosterhout <kleptog@svana.org> writes:

Hmm, depends. It's not asked often, that for sure. Yet everytime it
comes up I keep forgetting if I should be breaking on errstart, errmsg
or something else. One of these days I might just write it on a post-it
note next to my computer.

I always break on errfinish myself. At one time elog didn't go through
errstart (it may still not, I forget) so errfinish was the only
certainly common point for catching both elog and ereport. Another
advantage is that by that point, all the error info is set up and you
can inspect it if you want to.

- Note that DEBUG level message will trigger
- also so you might need to "cont" a few times to get the error you
- want.

Also, control doesn't come to errfinish at all unless the message is
going to be printed, so the DEBUG-message problem goes away.

regards, tom lane

Matteo Beccati <php@beccati.com> writes:

(gdb) bt
#0 errfinish (dummy=0) at elog.c:346
#1 0x08265896 in elog_finish (elevel=20, fmt=0x831858c "invalid memory
alloc request size %lu") at elog.c:930
#2 0x0827b5cf in MemoryContextAlloc (context=0x85b2238,
size=4279476584) at mcxt.c:505
#3 0x080b6a16 in GetMultiXactIdMembers (multi=301994, xids=0xbfbfaba4)
at multixact.c:935
#4 0x080b6271 in MultiXactIdIsRunning (multi=301994) at multixact.c:373
#5 0x0828347d in HeapTupleSatisfiesUpdate (tuple=0x28ccbb40, curcid=13,
buffer=756) at tqual.c:620

Well, this apparently indicates a bug in the new multixact code, but
there's not enough info here to figure out what went wrong. Can you
create a test case that will let someone else reproduce the problem?

regards, tom lane

Hi Tom,

Well, this apparently indicates a bug in the new multixact code, but
there's not enough info here to figure out what went wrong. Can you
create a test case that will let someone else reproduce the problem?

Unfortunately the error pops up randomly in a very complex app/db and I
am unable to produce a test case :(

Lat me know what other I can do to help fixing the bug.

Best regards
--
Matteo Beccati
http://phpadsnew.com
http://phppgads.com

OK, developer's FAQ updated to mention errfinish,

---------------------------------------------------------------------------

Tom Lane wrote:

Martijn van Oosterhout <kleptog@svana.org> writes:

Hmm, depends. It's not asked often, that for sure. Yet everytime it
comes up I keep forgetting if I should be breaking on errstart, errmsg
or something else. One of these days I might just write it on a post-it
note next to my computer.

I always break on errfinish myself. At one time elog didn't go through
errstart (it may still not, I forget) so errfinish was the only
certainly common point for catching both elog and ereport. Another
advantage is that by that point, all the error info is set up and you
can inspect it if you want to.

- Note that DEBUG level message will trigger
- also so you might need to "cont" a few times to get the error you
- want.

Also, control doesn't come to errfinish at all unless the message is
going to be printed, so the DEBUG-message problem goes away.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

On Thu, Oct 27, 2005 at 03:45:16PM +0200, Matteo Beccati wrote:

Hi Tom,

Well, this apparently indicates a bug in the new multixact code, but
there's not enough info here to figure out what went wrong. Can you
create a test case that will let someone else reproduce the problem?

Unfortunately the error pops up randomly in a very complex app/db and I
am unable to produce a test case :(

Go up a few levels to GetMultiXactIdMembers and type "info locals", see
if we can get the values of some of the variables there. Also, if you
can turn the debugging down to -O0, that will make the results in gdb
much more reliable.

It's clear at least that "length" is negative, but what about the other
variables...

Do you use a lot of subtransactions, function, savepoints, anything
like that?

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Matteo Beccati wrote:

Hi Tom,

Well, this apparently indicates a bug in the new multixact code, but
there's not enough info here to figure out what went wrong. Can you
create a test case that will let someone else reproduce the problem?

Unfortunately the error pops up randomly in a very complex app/db and I
am unable to produce a test case :(

Lat me know what other I can do to help fixing the bug.

It would be good to see the contents of MultiXactState. I suspect
there's a race condition in the MultiXact code.

--
Alvaro Herrera Valdivia, Chile ICBM: S 39� 49' 17.7", W 73� 14' 26.8"
"El realista sabe lo que quiere; el idealista quiere lo que sabe" (An�nimo)

Hi,

Go up a few levels to GetMultiXactIdMembers and type "info locals", see
if we can get the values of some of the variables there. Also, if you
can turn the debugging down to -O0, that will make the results in gdb
much more reliable.

It's clear at least that "length" is negative, but what about the other
variables...

I already recompiled all with -O0 to be sure that I was able to have a
backtrace. This is the full bt:

#2 0x0827b5cf in MemoryContextAlloc (context=0x856bcc8,
size=4278026492) at mcxt.c:505
__func__ = "MemoryContextAlloc"
#3 0x080b6a16 in GetMultiXactIdMembers (multi=320306, xids=0xbfbfaba4)
at multixact.c:935
pageno = 156
prev_pageno = 156
entryno = 819
slotno = 2
offptr = (MultiXactOffset *) 0x286536ac
offset = 4235201
length = -4235201
i = 138425096
nextMXact = 320308
tmpMXact = 320307
nextOffset = 4235265
ptr = (TransactionId *) 0xbfbfab78

Do you use a lot of subtransactions, function, savepoints, anything
like that?

I just removed a subtransaction that I put in a function that was used
to capture the deadlock errors. That subtransaction was actually useless
because I removed the FOR UPDATE clause that was causing the deadlock,
but the alloc error is still there. I'll try to search through the code
to find some other subtransactions.

Best regards
--
Matteo Beccati
http://phpadsnew.com
http://phppgads.com

Hi Alvaro,

It would be good to see the contents of MultiXactState. I suspect
there's a race condition in the MultiXact code.

Good, but... where do I find the contents of MultiXactState? ;)

Best regards
--
Matteo Beccati
http://phpadsnew.com
http://phppgads.com

Matteo Beccati wrote:

Hi Alvaro,

It would be good to see the contents of MultiXactState. I suspect
there's a race condition in the MultiXact code.

Good, but... where do I find the contents of MultiXactState? ;)

Huh, it should be a global variable. Try

p *MultiXactState

--
Alvaro Herrera http://www.amazon.com/gp/registry/5ZYLFMCVHXC
"Aprender sin pensar es in�til; pensar sin aprender, peligroso" (Confucio)

Matteo Beccati wrote:

#2 0x0827b5cf in MemoryContextAlloc (context=0x856bcc8,
size=4278026492) at mcxt.c:505
__func__ = "MemoryContextAlloc"
#3 0x080b6a16 in GetMultiXactIdMembers (multi=320306, xids=0xbfbfaba4)
at multixact.c:935
pageno = 156
prev_pageno = 156
entryno = 819
slotno = 2
offptr = (MultiXactOffset *) 0x286536ac
offset = 4235201
length = -4235201
i = 138425096
nextMXact = 320308
tmpMXact = 320307
nextOffset = 4235265
ptr = (TransactionId *) 0xbfbfab78

Whoa. length = *offptr - offset, which means that the datum stored at
offptr is 0. I think the problem is that CreateMultiXactId calls
GetNewMultiXactId and then RecordNewMultiXact, and the lock is released
between the calls. So one backend could try to read the offset before
another one had the time to finish writing it.

--
Alvaro Herrera Developer, http://www.PostgreSQL.org
"No single strategy is always right (Unless the boss says so)"
(Larry Wall)

Hi Alvaro,

It would be good to see the contents of MultiXactState. I suspect
there's a race condition in the MultiXact code.

Good, but... where do I find the contents of MultiXactState? ;)

Huh, it should be a global variable. Try

p *MultiXactState

Done:

(gdb) p *MultiXactState
$1 = {nextMXact = 320308, nextOffset = 4235265, lastTruncationPoint =
302016, perBackendXactIds = {0}}

Best regards
--
Matteo Beccati
http://phpadsnew.com
http://phppgads.com

Alvaro Herrera <alvherre@alvh.no-ip.org> writes:

I think the problem is that CreateMultiXactId calls
GetNewMultiXactId and then RecordNewMultiXact, and the lock is released
between the calls. So one backend could try to read the offset before
another one had the time to finish writing it.

Ugh, yes, that is clearly a hole :-( even if it turns out not to explain
Matteo's observation.

I don't see any easy way to fix this except by introducing a lot more
locking than is there now --- ie, holding the MultiXactGenLock until the
new mxact's starting offset has been written to disk. Any better ideas?

regards, tom lane