SEO

[
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,33 4,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 processing the 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


---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

"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

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

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

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

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


---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

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


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

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

---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

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

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly