Date: 2016-09-01 12:43:38 +0200
From: Richard Hughes <<richard.monetdb>>
To: GDK devs <>
Version: 11.21.19 (Jul2015-SP4)
CC: @lsidir

Last updated: 2016-12-21 13:07:24 +0100

Comment 22342

Date: 2016-09-01 12:43:38 +0200
From: Richard Hughes <<richard.monetdb>>

I've got this core dump (from Jul2015 b9cb28d6243b):

0 0x00007f1523ef1b6e in candscan_lng (b=, s=,
bn=, tl=0x7f11be28fcd0, th=0x7f151b13ca20,
equi=, anti=0, r=0, q=131071, cnt=1, off=42133790,
dst=0x7f11bdfdd000, candlist=0x7f11bdfcd000, maximum=131071,
use_imprints=1, hval=, lval=,
hi=, li=) at gdk_select.c:868
1 0x00007f1523f4bf8c in BAT_scanselect (use_imprints=,
maximum=, hval=, lval=,
anti=, equi=, hi=,
li=, th=, tl=,
bn=, s=, b=)
at gdk_select.c:952
2 BATsubselect (b=0x32fe3e0, s=0x7f11bb91e7b0, tl=0x7f11be28fcd0,
th=0x2ca6a50, li=1, hi=1, anti=0) at gdk_select.c:1733
3 0x00007f15245cb6a4 in ALGsubselect2 (result=0x7f11be381cd0, bid=0x0,
sid=0x7f11c7cefba8, low=0x7f11be28fcd0, high=0x2ca6a50, li=0x2ca6a50 "",
hi=0x7f11be28fe90 "", anti=0x7f11be28fe90 "") at algebra.c:343
4 0x00007f152456a751 in malCommandCall (stk=,
pci=) at mal_interpreter.c:119
5 0x00007f152456ba9b in runMALsequence (cntxt=0x7f11bdfcd008,
mb=0x7f150402b480, startpc=-942736472, stoppc=46819920,
stk=0x7f11be27d020, env=0x2ca6a50, pcicaller=0x0) at mal_interpreter.c:655
6 0x00007f152456d9d8 in DFLOWworker (T=0x7f11bdfcd008) at mal_dataflow.c:378
7 0x00007f1522c6e0a4 in start_thread (arg=0x7f151b13d700)
at pthread_create.c:309
8 0x00007f15229a387d in clone ()
at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
(gdb) i loc
icnt = 193400
limit =
i =
e = 46819920
dcnt = 154966
l =
d = 0x7f11c7c58650
rpp = 3 '\003'
im = 0x7f11c4c20820
mask = 72057594037927936
tpe =
innermask = 0
lbin =
hbin =
vl = 3163513996443648
vh = 3163518291410943
imp_min =
imp_max =
v =
nil =
src = 0x7f132e8448f0
basesrc =
o = 0
w = 46219307
p = 131072
pr_off = 42133790
imprints = 0x7f150c03f5e0

The address is specifically this bit of code from near the end of the impscheck macro:

while (p <= q && o < e) {
	p++;
	CAND;    // expands to:  o = *candlist++
}

Notice that in my core dump p == q+1. The crash is in dereferencing candlist.

Before I launch in to a big debugging session, can I ask somebody to review that piece of code? I don't understand the high-level picture, but it looks different to the other two while loops in the impscheck macro and hence may be subject to off-by-one bugs. This is an especially attractive theory because the candlist has a nice round length.

See also 83a3b3fc61a9 which modified the other two while loops but not that one.

If you tell me that the code is correct then I'll start looking elsewhere (I can't reproduce it now, probably because the underlying data has long since changed), but I can save myself a huge amount of time if my guess is right.

Comment 22343

Date: 2016-09-01 14:03:32 +0200
From: @lsidir

Hi Richard,

there is a good chance that if you add "if (p <= q)"
before CAND; the problem will be solved. That is

p++;

• if (p <= q)
  CAND;

The border cases of imprints have always been tricky and since I understand that you cannot reproduce the problem, we can add this small sanity check.

Is there any way to reproduce the bug so we can solve it in a more "scientific" way?

Comment 22346

Date: 2016-09-01 16:29:29 +0200
From: Richard Hughes <<richard.monetdb>>

Reproducing will not be easy. The query which was executing at the time had 30418 MAL statements. I assume I would need to reverse-engineer all statements preceeding the one which crashed so that I can construct an original data set which causes a candlist of exactly the right length in order to put the last element right at the end of a page (and then hope that mmap positions it such that the next page really is absent).

I can think of a couple of possibly-easier alternatives:

1. Write a small application directly against the GDK library which calls BATsubselect() with some carefully-chosen parameters? I can get all the BAT attributes out of the core dump, but not the data itself (my coredump_filter doesn't write the contents of mmaped files).

2. Put several slow, paranoid bounds-checking asserts in the body of candscan and thence try to reproduce it without needing a candlist of exactly the right size (although I'd still have to figure out how to create an imprint with the correct pattern).

Do you have a recommendation (or any other ideas)?

Comment 22347

Date: 2016-09-01 16:58:17 +0200
From: @lsidir

I am trying to reason why that specific line is p<=q and not p<q.

This is the case where imprints mask is empty and we have to advance until either a new imprint, or the column has reached the end, or the candidate lists has reached the end. From your core dump I see that p > q (p = 131072 and q = 131071), so candlist should not be advanced by one. I still think that adding
the check

line 301: p++;

•     if(p<=q)
  

line 302: CAND++;

should solve the problem.

Can you add that line, recompile, and test with your data for a few days and see if you get again a core dump?

I can do this change to our default branch and test but most likely I will not see the problem since we have not seen it before.

Reproducing the exact conditions will be a pain that is why I am trying to reason about it:)

Comment 22348

Date: 2016-09-01 17:26:38 +0200
From: Richard Hughes <<richard.monetdb>>

Is it possible that it's off-by-two?

(gdb) p *s->S
$1 = {tid = 139728631629569, stamp = 269762, copiedtodisk = 0, dirty = 1,
dirtyflushed = 0, descdirty = 1, restricted = 1, persistence = 1, role = 1,
unused = 0, sharecnt = 0, map_head = 0 '\000', map_tail = 0 '\000',
map_hheap = 0 '\000', map_theap = 0 '\000', deleted = 0, first = 0,
inserted = 0, count = 131071, capacity = 131072}

Given count=131071, it presumably shouldn't be reading the previous element either. That would make the fix something like:

while (p < q - 1 && o < e) {
	p++;
	CAND;
}
if (p < q && o < e)
	p++;

(I hoisted the duplicate p < q check out of the inner loop)

I can certainly test with any patch you like, however bear in mind that this system has been running for about a year now without my having seen this crash before - a few days testing is unlikely to convince me that the problem is no longer present.

Comment 22349

Date: 2016-09-01 17:46:25 +0200
From: @lsidir

If that is the case, then give me a few days to reason about it and try to reproduce it before we do any code change.

Comment 22351

Date: 2016-09-01 18:28:27 +0200
From: Richard Hughes <<richard.monetdb>>

OK. Thanks, and good luck!

Comment 22378

Date: 2016-09-19 14:19:58 +0200
From: Richard Hughes <<richard.monetdb>>

I had a bit of time, so started looking at this again. I have a small test case, which doesn't crash but can be observed in the debugger to overrun the array:

create table foo (a bigint,b bigint,c bigint);
insert into foo (a,b,c) select value,(value16777219)%5059,(value20000033)%5099 from generate_series(cast(1 as bigint),10000);
select * from foo where b=1888 and c between 1234 and 1240;

The resultant MAL (with a few annotations added by me) is:

function user.s3_1(A0:lng,A1:lng,A2:lng):void;
X_60:void := querylog.define("explain select * from foo where b=1888 and c between 1234 and 1240;","default_pipe",46);
X_34 := bat.new(nil:oid,nil:str);
X_42 := bat.append(X_34,"sys.foo");
X_50 := bat.append(X_42,"sys.foo");
X_55 := bat.append(X_50,"sys.foo");
X_37 := bat.new(nil:oid,nil:str);
X_44 := bat.append(X_37,"a");
X_51 := bat.append(X_44,"b");
X_56 := bat.append(X_51,"c");
X_38 := bat.new(nil:oid,nil:str);
X_45 := bat.append(X_38,"bigint");
X_52 := bat.append(X_45,"bigint");
X_57 := bat.append(X_52,"bigint");
X_39 := bat.new(nil:oid,nil:int);
X_47 := bat.append(X_39,64);
X_53 := bat.append(X_47,64);
X_58 := bat.append(X_53,64);
X_41 := bat.new(nil:oid,nil:int);
X_49 := bat.append(X_41,0);
X_54 := bat.append(X_49,0);
X_59 := bat.append(X_54,0);
X_4 := sql.mvc();
X_8:bat[:lng] := sql.bind(X_4,"sys","foo","c",0);
X_16:bat[:lng] := sql.bind(X_4,"sys","foo","b",0);
C_5:bat[:oid] := sql.tid(X_4,"sys","foo");
C_71 := algebra.subselect(X_16,C_5,A0,A0,true,false,false);
(C_18,r1_22) := sql.bind(X_4,"sys","foo","b",2);
C_72 := algebra.subselect(r1_22,nil:bat[:oid],A0,A0,true,false,false);
X_20:bat[:lng] := sql.bind(X_4,"sys","foo","b",1);
C_74 := algebra.subselect(X_20,C_5,A0,A0,true,false,false);
C_21 := sql.subdelta(C_71,C_5,C_18<n=0>,C_72,C_74); C_18=[4314,9373]
C_75 := algebra.subselect(X_8<n=9999>,C_21<n=2>,A1=1234,A2=1240,true,true,false); HERE
(C_11,r1_11) := sql.bind(X_4,"sys","foo","c",2);
C_76 := algebra.subselect(r1_11,nil:bat[:oid],A1,A2,true,true,false);
X_14:bat[:lng] := sql.bind(X_4,"sys","foo","c",1);
C_77 := algebra.subselect(X_14,C_21,A1,A2,true,true,false);
C_24 := sql.subdelta(C_75,C_21,C_11,C_76,C_77);
X_25:bat[:lng] := sql.bind(X_4,"sys","foo","a",0);
(C_27,r1_35) := sql.bind(X_4,"sys","foo","a",2);
X_29:bat[:lng] := sql.bind(X_4,"sys","foo","a",1);
X_30 := sql.projectdelta(C_24,X_25,C_27,r1_35,X_29);
X_31 := sql.projectdelta(C_24,X_16,C_18,r1_22,X_20);
X_32 := sql.projectdelta(C_24,X_8,C_11,r1_11,X_14);
sql.resultSet(X_55,X_56,X_57,X_58,X_59,X_30,X_31,X_32);
end user.s3_1;

I put a breakpoint on the "while (p <= q && o < e)" line and here's some of my gdb session. [Note that all line numbers are bogus because I've expanded-out all the macros in order to be able to step through].

Breakpoint 1, candscan_lng (b=0x64d400, s=0x7fffe416b480, bn=0x7fffe410fec0,
tl=0x7fffe41d23c0, th=0x7fffe41d23e0, li=1, hi=1, equi=0, anti=0, lval=1,
hval=1, r=0, q=2, cnt=0, off=0, dst=0x7fffe41d95a0,
candlist=0x7fffe420f588, maximum=2, use_imprints=1) at gdk_select.c:739
739 while (p <= q && o < e) {
(gdb) i loc
icnt = 539
limit = 8
i = 4312
e = 4320
dcnt = 0
l = 1250
d = 0x7fffe4190e28
rpp = 3 '\003'
im = 0x7fffe418e710
mask = 16384
tpe = 11
innermask = 0
lbin = 14
hbin = 14
vl = 1234
vh = 1240
imp_min = 0
imp_max = 5098
v = 12096
nil = -9223372036854775808
minval = -9223372036854775807
maxval = 9223372036854775807
src = 0x7fffe40d8340
basesrc = 0x7fffe40d8340
o = 4314
w = 9374
p = 0
pr_off = 0
imprints = 0x7fffe419cf50
PRETTY_FUNCTION = "candscan_lng"
(gdb) x/3g candlist
0x7fffe420f588: 9373 9998
0x7fffe420f598: -2604246222170760229
(gdb) up
1 0x00007ffff7291532 in BAT_scanselect (b=0x64d400, s=0x7fffe416b480,
bn=0x7fffe410fec0, tl=0x7fffe41d23c0, th=0x7fffe41d23e0, li=1, hi=1,
equi=0, anti=0, lval=1, hval=1, maximum=2, use_imprints=1)
at gdk_select.c:1166
1166 cnt = candscan_lng(scanargs);
(gdb) p *s->S
$1 = {tid = 140737189574401, stamp = 2104, copiedtodisk = 0, dirty = 1,
dirtyflushed = 0, descdirty = 1, restricted = 1, persistence = 1, role = 1,
unused = 0, sharecnt = 0, deleted = 0, first = 0, inserted = 0, count = 2,
capacity = 10240}
(gdb) p *s->T
$2 = {id = 0x7ffff75c914b "t", width = 8, type = 6 '\006', shift = 3 '\003',
varsized = 0, key = 1, dense = 0, nonil = 1, nil = 0, sorted = 1,
revsorted = 0, align = 1045647, nokey = {0, 0}, nosorted = 0,
norevsorted = 0, nodense = 0, seq = 0, heap = {free = 16, size = 81920,
base = 0x7fffe420f580 "\332\020", filename = 0x7fffe41a28f0 "44.tail",
copied = 0, hashash = 0, forcemap = 0, storage = STORE_MEM,
newstorage = STORE_MEM, dirty = 0 '\000', farmid = 0 '\000',
parentid = 0}, vheap = 0x0, hash = 0x0, imprints = 0x0, props = 0x0}
(gdb) x/4g s->T.heap.base
0x7fffe420f580: 4314 9373
0x7fffe420f590: 9998 -2604246222170760229

...skip a few hundred iterations of the for(icnt) loop...

Breakpoint 1, candscan_lng (b=0x64d400, s=0x7fffe416b480, bn=0x7fffe410fec0,
tl=0x7fffe41d23c0, th=0x7fffe41d23e0, li=1, hi=1, equi=0, anti=0, lval=1,
hval=1, r=0, q=2, cnt=0, off=0, dst=0x7fffe41d95a0,
candlist=0x7fffe420f590, maximum=2, use_imprints=1) at gdk_select.c:739
739 while (p <= q && o < e) {
(gdb) i loc
icnt = 1171
limit = 8
i = 9368
e = 9376
dcnt = 0
l = 1250
d = 0x7fffe4190e28
rpp = 3 '\003'
im = 0x7fffe418e710
mask = 16384
tpe = 11
innermask = 0
lbin = 14
hbin = 14
vl = 1234
vh = 1240
imp_min = 0
imp_max = 5098
v = 12096
nil = -9223372036854775808
minval = -9223372036854775807
maxval = 9223372036854775807
src = 0x7fffe40d8340
basesrc = 0x7fffe40d8340
o = 9373
w = 9374
p = 1
pr_off = 0
imprints = 0x7fffe419cf50
PRETTY_FUNCTION = "candscan_lng"

At this point p<=q && o<e and candlist is already at the end of the BAT (==s->T.heap.base+s->T.width*s->S.count). It is only the fluke that the element off the end of the array happens to be larger that stops the while loop going round twice.

This is certainly good experimental evidence of a bug. I still need you to think about why the code was (clearly intentionally) written that way. Is it possible that o<e was expected always to be false at the end of the loop?

Comment 24533

Date: 2016-10-18 14:15:45 +0200
From: @sjoerdmullender

Looks like changeset 84a66f61f8fe wasn't complete. I think the <= should indeed be <. Running tests now.

Comment 24536

Date: 2016-10-18 15:44:41 +0200
From: MonetDB Mercurial Repository <>

Changeset f7194ce0de47 made by Sjoerd Mullender sjoerd@acm.org in the MonetDB repo, refers to this bug.

For complete details, see http//devmonetdborg/hg/MonetDB?cmd=changeset;node=f7194ce0de47

Changeset description:

Off-by-one error, completing changeset [84a66f61f8fe](https://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=84a66f61f8fe) 
This (hopefully) fixes bug #4061.