Thread: crash on 8.2 and cvshead - failed to add item to the left sibling
[ Sorry if this is a duplicate -- resending since it hasn't made it to the list after 1 1/2 hour, possibly due to large attachment (?); here's a URL instead: http://www.joeconway.com/das_data_load_failure2.sql.gz ] We just came upon a crash bug in Postgres >= 8.2. The attached standalone script (just needs a database with plpgsql installed) reproduces the crash for me on 32-bit machines (i686) but NOT on 64 bit machines (x86_64), for Postgres 8.2 and cvs-head, but not on 8.1. We've verified this on about four 32 bit machines, and four 64 bit machines (including one each under vmware on the same host). All machines were some flavor of Red Hat, Fedora, or Gentoo. Here is the error: 8<-------------------------------------------------------------- das=# \i /home/jconway/pgsql/das_data_load_failure2.sql [...snip...] das_tbl_das_status_log ------------------------ (1 row) psql:/home/jconway/pgsql/das_data_load_failure2.sql:419: PANIC: failed to add item to the left sibling for "pk_status_log_2007_01_4_10" CONTEXT: COPY das_status_log_2007_01_4_10, line 27: "10 2007-Jan-25 03:06:59.372266 -0800 r_x_data 406,386,482,342,338,338,330,310,322,330,314,326,334,31..." psql:/home/jconway/pgsql/das_data_load_failure2.sql:420: server closed the connection unexpectedly This probably means the server terminated abnormally before or while processingthe request. psql:/home/jconway/pgsql/das_data_load_failure2.sql:420: connection to server was lost 8<-------------------------------------------------------------- Here is a backtrace: 8<-------------------------------------------------------------- #0 0x00d2f402 in __kernel_vsyscall () #1 0x42901d40 in raise () from /lib/libc.so.6 #2 0x42903591 in abort () from /lib/libc.so.6 #3 0x082ed82e in errfinish (dummy=0) at elog.c:449 #4 0x082ee729 in elog_finish (elevel=22, fmt=0x832c0c4 "failed to add item to the %s for \"%s\"") at elog.c:937 #5 0x080b0483 in _bt_pgaddtup (rel=0xb5b4302c, page=0x86c6bfc "", itemsize=48, itup=0xb5e49d14, itup_off=36, where=0x832b826 "left sibling") at nbtinsert.c:1654 #6 0x080ae849 in _bt_split (rel=0xb5b4302c, buf=252, firstright=40, newitemoff=40, newitemsz=1312, newitem=0x8680714, newitemonleft=0 '\0') at nbtinsert.c:843 #7 0x080ad965 in _bt_insertonpg (rel=0xb5b4302c, buf=252, stack=0x869c3b4, keysz=4, scankey=0x8681538, itup=0x8680714, afteritem=0, split_only_page=0 '\0') at nbtinsert.c:538 #8 0x080acd08 in _bt_doinsert (rel=0xb5b4302c, itup=0x8680714, index_is_unique=1 '\001', heapRel=0xb5b42c7c) at nbtinsert.c:141 #9 0x080b484a in btinsert (fcinfo=0xbfc80380) at nbtree.c:224 #10 0x082f393c in FunctionCall6 (flinfo=0x866ef9c, arg1=3048484908, arg2=3217557044, arg3=3217557012, arg4=141339656, arg5=3048483964, arg6=1) at fmgr.c:1267 #11 0x080ab427 in index_insert (indexRelation=0xb5b4302c, values=0xbfc80634, isnull=0xbfc80614 "", heap_t_ctid=0x86cac08, heapRelation=0xb5b42c7c, check_uniqueness=1 '\001') at indexam.c:196 #12 0x081a08e5 in ExecInsertIndexTuples (slot=0x86899e4, tupleid=0x86cac08, estate=0x862cc14, is_vacuum=0 '\0') at execUtils.c:1088 #13 0x0814fcd9 in CopyFrom (cstate=0x863a590) at copy.c:2082 #14 0x0814d90b in DoCopy (stmt=0x860bd14) at copy.c:1141 #15 0x082555a7 in ProcessUtility (parsetree=0x860bd14, params=0x0, dest=0x860bbe4, completionTag=0xbfc80d1e "") at utility.c:635 #16 0x08253bff in PortalRunUtility (portal=0x862ec1c, query=0x860bd70, dest=0x860bbe4, completionTag=0xbfc80d1e "") at pquery.c:1063 #17 0x08253d72 in PortalRunMulti (portal=0x862ec1c, dest=0x860bbe4, altdest=0x860bbe4, completionTag=0xbfc80d1e "") at pquery.c:1131 #18 0x08253482 in PortalRun (portal=0x862ec1c, count=2147483647, dest=0x860bbe4, altdest=0x860bbe4, completionTag=0xbfc80d1e "") at pquery.c:700 #19 0x0824deb2 in exec_simple_query (query_string=0x860b9cc "copy das_status_log_2007_01_4_10 from stdin;") at postgres.c:939 #20 0x08251b5e in PostgresMain (argc=4, argv=0x85b1c80, username=0x85b1c50 "postgres") at postgres.c:3424 8<-------------------------------------------------------------- Joe
"Joe Conway" <mail@joeconway.com> writes: > psql:/home/jconway/pgsql/das_data_load_failure2.sql:419: PANIC: failed > to add item to the left sibling for "pk_status_log_2007_01_4_10" Was this preceded by a WARNING? Was the server running with a log_min_messages low enough to log WARNINGs? I probably can't help find the bug but I can see that would be helpful as there are three branches of the code that can result in this and two of them log warnings before returning the invalid offset which causes the panic. -- Gregory Stark EnterpriseDB http://www.enterprisedb.com
Gregory Stark wrote: > "Joe Conway" <mail@joeconway.com> writes: > >> psql:/home/jconway/pgsql/das_data_load_failure2.sql:419: PANIC: failed >> to add item to the left sibling for "pk_status_log_2007_01_4_10" > > Was this preceded by a WARNING? > > Was the server running with a log_min_messages low enough to log WARNINGs? > > I probably can't help find the bug but I can see that would be helpful as > there are three branches of the code that can result in this and two of them > log warnings before returning the invalid offset which causes the panic. FWIW I can reproduce the crash on 8.2 and I don't get a WARNING either ... Stefan
Stefan Kaltenbrunner wrote: > Gregory Stark wrote: >> "Joe Conway" <mail@joeconway.com> writes: >> >>> psql:/home/jconway/pgsql/das_data_load_failure2.sql:419: PANIC: failed >>> to add item to the left sibling for "pk_status_log_2007_01_4_10" >> Was this preceded by a WARNING? >> >> Was the server running with a log_min_messages low enough to log WARNINGs? >> >> I probably can't help find the bug but I can see that would be helpful as >> there are three branches of the code that can result in this and two of them >> log warnings before returning the invalid offset which causes the panic. > > FWIW I can reproduce the crash on 8.2 and I don't get a WARNING either ... I don't get the WARNING, and I'm using stock default postgresql.conf. Joe
Joe Conway wrote: > We just came upon a crash bug in Postgres >= 8.2. The attached > standalone script (just needs a database with plpgsql installed) > reproduces the crash for me on 32-bit machines (i686) but NOT on 64 bit > machines (x86_64), for Postgres 8.2 and cvs-head, but not on 8.1. We've > verified this on about four 32 bit machines, and four 64 bit machines > (including one each under vmware on the same host). All machines were > some flavor of Red Hat, Fedora, or Gentoo. Hmm. There seems to be something wrong in the free space calculation in the algorithm for choosing the right split location. I'll dig deeper, unless someone beats me to it.. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas wrote: > Joe Conway wrote: >> We just came upon a crash bug in Postgres >= 8.2. The attached >> standalone script (just needs a database with plpgsql installed) >> reproduces the crash for me on 32-bit machines (i686) but NOT on 64 bit >> machines (x86_64), for Postgres 8.2 and cvs-head, but not on 8.1. We've >> verified this on about four 32 bit machines, and four 64 bit machines >> (including one each under vmware on the same host). All machines were >> some flavor of Red Hat, Fedora, or Gentoo. > > Hmm. There seems to be something wrong in the free space calculation in > the algorithm for choosing the right split location. I'll dig deeper, > unless someone beats me to it.. I think I found it. The page splitting code didn't take into account that when the new item is the first one on the right page, it also becomes the high key of the left page. The fact that this test case triggered it in 32 bit machines and not on 64 bit machines was a coincidence. Patch attached. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com Index: src/backend/access/nbtree/nbtinsert.c =================================================================== RCS file: /home/hlinnaka/pgcvsrepository/pgsql/src/backend/access/nbtree/nbtinsert.c,v retrieving revision 1.147 diff -c -r1.147 nbtinsert.c *** src/backend/access/nbtree/nbtinsert.c 5 Jan 2007 22:19:23 -0000 1.147 --- src/backend/access/nbtree/nbtinsert.c 25 Jan 2007 15:50:36 -0000 *************** *** 1153,1159 **** /* need to try it both ways! */ _bt_checksplitloc(&state, offnum, leftfree, rightfree, true, itemsz); ! /* here we are contemplating newitem as first on right */ _bt_checksplitloc(&state, offnum, leftfree, rightfree, false, newitemsz); } --- 1153,1166 ---- /* need to try it both ways! */ _bt_checksplitloc(&state, offnum, leftfree, rightfree, true, itemsz); ! ! /* here we are contemplating newitem as first on right. ! * ! * The new item is going to be the high key of the left page ! * instead of the current item that we subtracted from leftfree ! * above. ! */ ! leftfree = leftfree + ((int) itemsz) - ((int) newitemsz); _bt_checksplitloc(&state, offnum, leftfree, rightfree, false, newitemsz); }
Heikki Linnakangas wrote: > Heikki Linnakangas wrote: >> Joe Conway wrote: >>> We just came upon a crash bug in Postgres >= 8.2. The attached >>> standalone script (just needs a database with plpgsql installed) >>> reproduces the crash for me on 32-bit machines (i686) but NOT on 64 bit >>> machines (x86_64), for Postgres 8.2 and cvs-head, but not on 8.1. We've >>> verified this on about four 32 bit machines, and four 64 bit machines >>> (including one each under vmware on the same host). All machines were >>> some flavor of Red Hat, Fedora, or Gentoo. >> Hmm. There seems to be something wrong in the free space calculation in >> the algorithm for choosing the right split location. I'll dig deeper, >> unless someone beats me to it.. > > I think I found it. The page splitting code didn't take into account > that when the new item is the first one on the right page, it also > becomes the high key of the left page. The fact that this test case > triggered it in 32 bit machines and not on 64 bit machines was a > coincidence. > > Patch attached. Thanks! That seems to have fixed it. Both the original test case and a somewhat simplified one that we created a few minutes ago work fine now, on 8.2 and cvs-head. The simplified case is still about 22K gzipped -- let me know if you want a copy and I'll send it off list. Joe
Heikki Linnakangas <heikki@enterprisedb.com> writes:
> Hmm. There seems to be something wrong in the free space calculation in
> the algorithm for choosing the right split location. I'll dig deeper,
> unless someone beats me to it..
I seem to recall that that part of the code was changed recently, so you
might try looking at the CVS history for hints. This is probably
recently introduced, else we'd have seen it reported before :-(
regards, tom lane
Tom Lane wrote: > Heikki Linnakangas <heikki@enterprisedb.com> writes: >> Hmm. There seems to be something wrong in the free space calculation in >> the algorithm for choosing the right split location. I'll dig deeper, >> unless someone beats me to it.. > > I seem to recall that that part of the code was changed recently, so you > might try looking at the CVS history for hints. This is probably > recently introduced, else we'd have seen it reported before :-( I'm afraid the bug has been there for ages, but the 90%-fillfactor on rightmost page patch made it much more likely to get triggered. With a 50% or 67% target for splitting, there is a lot more wiggle room. To see what's going on, I added some logs to the split code to print out the free space on both halves as calculated by findsplitloc, and the actual free space on the pages after split. I'm seeing a discrepancy of 4 bytes on the right half; actual space free on right page after split is 4 bytes less than anticipated. That's on every split, not just in some corner cases. That's not a big deal, but I'll take a closer look tomorrow to see what's missing from the calculations. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas <heikki@enterprisedb.com> writes:
> I think I found it. The page splitting code didn't take into account
> that when the new item is the first one on the right page, it also
> becomes the high key of the left page.
Good catch! This is something that would not make a difference with
equal-sized keys (a very common case) and also would never matter unless
the "best available" split was pretty awful, which would require very
large index entries. So that explains why it'd not been seen before.
AFAICS the bug must go back a long way though; I'm not sure why Joe
failed to reproduce on 8.1. Did we change the size of the page overhead
in btree indexes recently?
regards, tom lane
Heikki Linnakangas <heikki@enterprisedb.com> writes:
> I'm afraid the bug has been there for ages, but the 90%-fillfactor on
> rightmost page patch made it much more likely to get triggered.
But that patch has been there for ages too; the only new thing in 8.2 is
that the fillfactor is configurable, but its default is the same. So
I'm still wondering why the bug isn't seen in 8.1. (Joe, did you try
anything older than 8.1?)
> To see what's going on, I added some logs to the split code to print out
> the free space on both halves as calculated by findsplitloc, and the
> actual free space on the pages after split. I'm seeing a discrepancy of
> 4 bytes on the right half; actual space free on right page after split
> is 4 bytes less than anticipated.
Hm, mis-counting the positions of itempointers maybe?
> That's not a big deal, but I'll take a closer look
> tomorrow to see what's missing from the calculations.
OK, I've got some other things to worry about, will leave it to you.
regards, tom lane
Tom Lane wrote: > Heikki Linnakangas <heikki@enterprisedb.com> writes: >> I'm afraid the bug has been there for ages, but the 90%-fillfactor on >> rightmost page patch made it much more likely to get triggered. > > But that patch has been there for ages too; the only new thing in 8.2 is > that the fillfactor is configurable, but its default is the same. So > I'm still wondering why the bug isn't seen in 8.1. (Joe, did you try > anything older than 8.1?) I just tried on Postgres 8.0.8 -- no crash. Joe
Tom Lane wrote: > Heikki Linnakangas <heikki@enterprisedb.com> writes: >> I'm afraid the bug has been there for ages, but the 90%-fillfactor on >> rightmost page patch made it much more likely to get triggered. > > But that patch has been there for ages too; the only new thing in 8.2 is > that the fillfactor is configurable, but its default is the same. So > I'm still wondering why the bug isn't seen in 8.1. (Joe, did you try > anything older than 8.1?) The hardcoded fillfactor was 90% when building an index, and that's still the default. However, when inserting to an existing index, the fillfactor on the rightmost page was 2/3. It was changed to use the user-configurable fillfactor, which now defaults to 90%. Hmm. Now that I think of it, we might have the same bug in nbtsort.c. I'll have a look... -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas <heikki@enterprisedb.com> writes:
> Tom Lane wrote:
>> I'm still wondering why the bug isn't seen in 8.1.
> The hardcoded fillfactor was 90% when building an index, and that's
> still the default. However, when inserting to an existing index, the
> fillfactor on the rightmost page was 2/3. It was changed to use the
> user-configurable fillfactor, which now defaults to 90%.
Ah. I thought I remembered that those had been two separate changes,
but you're right, 8.1 and before always split 1:1 or 2:1. So it'd take
a really nasty corner case to expose the bug there.
regards, tom lane
Tom Lane wrote: > Heikki Linnakangas <heikki@enterprisedb.com> writes: >> To see what's going on, I added some logs to the split code to print out >> the free space on both halves as calculated by findsplitloc, and the >> actual free space on the pages after split. I'm seeing a discrepancy of >> 4 bytes on the right half; actual space free on right page after split >> is 4 bytes less than anticipated. > > Hm, mis-counting the positions of itempointers maybe? Found it: /* Count up total space in data items without actually scanning 'em */dataitemtotal = rightspace - (int) PageGetFreeSpace(page); This is 4 bytes off, because PageGetFreeSpace subtracts sizeof(ItemIdData) from the actual free space on page. We could do dataitemtotal = rightspace - ((int) PageGetFreeSpace(page) +sizeof(ItemIdData)); but that again would be 4 bytes off in the other direction if there's 0 bytes left on the page :(. IMHO the right fix is to modify PageGetFreeSpace not to do the subtraction, it's a hack anyway, but that means we have to go through and fix every caller of it. Or we can add a new PageGetReallyFreeSpace function and keep the old one for compatibility. What do we want? -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas <heikki@enterprisedb.com> writes:
> IMHO the right fix is to modify PageGetFreeSpace not to do the
> subtraction, it's a hack anyway, but that means we have to go through
> and fix every caller of it. Or we can add a new PageGetReallyFreeSpace
> function and keep the old one for compatibility. What do we want?
It'd probably be a good idea to take a look at each caller and see
whether it has a problem with that. I believe PageGetFreeSpace's
behavior is actually the right thing for many of 'em. The idea is that
subtracting the 4 bytes is often necessary and always safe/conservative
(but is that true in this case? We're overestimating dataitemtotal,
can that hurt us?). Is it worth changing each caller to try to account
exactly for those 4 bytes?
In short, I'm inclined to leave the function alone unless changing it
can be shown to be a win for most callers. Add a new function
(perhaps PageGetExactFreeSpace would be a better name).
Keep in mind also that we need a minimal-change version for
back-patching. If this is cleanup rather than bug fix, please
submit it separately.
regards, tom lane
Heikki Linnakangas <heikki@enterprisedb.com> writes:
>> Hmm. There seems to be something wrong in the free space calculation in
>> the algorithm for choosing the right split location. I'll dig deeper,
>> unless someone beats me to it..
> I think I found it. The page splitting code didn't take into account
> that when the new item is the first one on the right page, it also
> becomes the high key of the left page. The fact that this test case
> triggered it in 32 bit machines and not on 64 bit machines was a
> coincidence.
> Patch attached.
Patch applied. I tried Joe's example with the maximum and minimum
possible fillfactors, and saw no failure, which may or may not prove
a lot. Are you still concerned about the PageGetFreeSpace issue?
regards, tom lane
Tom Lane wrote: > Are you still concerned about the PageGetFreeSpace issue? Not anymore. The failure case I had in mind was not being able to find any valid split points when a page is full of max-sized index tuples. On a closer look, that doesn't seem to be a problem. Even though checksplitloc would incorrectly consider the split (HIKEY+item)-(HIKEY+item+item) as invalid, the split (HIKEY+item+item)-(HIKEY+item) is just as good. Similarly on the rightmost page, even if (HIKEY+item)-(item+item+item) is incorrectly considered as invalid, (HIKEY+item+item)-(item+item) is fine. There also seems to always be some slack space because of alignments. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com