Bug 2630 - Poor performance using length(...) = length(...) in conjuction with a equjoin
Summary: Poor performance using length(...) = length(...) in conjuction with a equjoin
Status: REOPENED
Alias: None
Product: SQL
Classification: Unclassified
Component: all (show other bugs)
Version: -- development
Hardware: x86_64 (amd64/em64t) Linux
: Normal enhancement
Assignee: SQL devs
URL:
Keywords: NONEEDTOTEST
Depends on:
Blocks:
 
Reported: 2010-07-22 19:14 CEST by Stefan de Konink
Modified: 2016-04-11 11:46 CEST (History)
3 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Stefan de Konink 2010-07-22 19:14:22 CEST
User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.99 Safari/533.4
Build Identifier: 

sql>plan select uitspraken.id, length(uitspraken.uitspraak)=length(uitspraken_new.uitspraak) from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id;
% .plan # table_name
% rel # name
% clob # type
% 116 # length
project (
| join (
| | table(sys.uitspraken) [ uitspraken.id NOT NULL, uitspraken.uitspraak, uitspraken.%TID% NOT NULL ],
| | table(sys.uitspraken_new) [ uitspraken_new.id NOT NULL, uitspraken_new.uitspraak, uitspraken_new.%TID% NOT NULL ]
| ) [ uitspraken.id NOT NULL = uitspraken_new.id NOT NULL ]
) [ uitspraken.id NOT NULL, =(length(uitspraken.uitspraak), length(uitspraken_new.uitspraak)) ]
sql>plan select uitspraken.id,  length(uitspraken.uitspraak), length(uitspraken_new.uitspraak) from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id and length(uitspraken.uitspraak) <> length(uitspraken_new.uitspraak);
% .plan # table_name
% rel # name
% clob # type
% 124 # length
project (
| join (
| | table(sys.uitspraken) [ uitspraken.id NOT NULL, uitspraken.uitspraak, uitspraken.%TID% NOT NULL ],
| | table(sys.uitspraken_new) [ uitspraken_new.id NOT NULL, uitspraken_new.uitspraak, uitspraken_new.%TID% NOT NULL ]
| ) [ uitspraken.id NOT NULL = uitspraken_new.id NOT NULL, length(uitspraken.uitspraak) != length(uitspraken_new.uitspraak) ]
) [ uitspraken.id NOT NULL, length(uitspraken.uitspraak), length(uitspraken_new.uitspraak) ]

First query finishes in 76ms, second doesn't finish fast enough.


sql>explain select uitspraken.id, length(uitspraken.uitspraak)=length(uitspraken_new.uitspraak) from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id;
% .explain # table_name
% mal # name
% clob # type
% 0 # length
function user.s1_1{autoCommit=true}():void;
    _2 := sql.mvc();
barrier _139 := language.dataflow();
    _71:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",0,0@0:oid,87752@0);
    _7:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",2);
    _76 := algebra.kdifference(_71,_7);
    _78 := algebra.semijoin(_7,_71);
    _80 := algebra.kunion(_76,_78);
    _11:bat[:oid,:oid]  := sql.bind_dbat(_2,"sys","uitspraken",1);
    _12 := bat.reverse(_11);
    _82 := algebra.kdifference(_80,_12);
    _13:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken_new","id",0);
    _15:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken_new","id",2);
    _16 := algebra.kdifference(_13,_15);
    _17 := algebra.kunion(_16,_15);
    _18:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken_new","id",1);
    _19 := algebra.kunion(_17,_18);
    _20:bat[:oid,:oid]  := sql.bind_dbat(_2,"sys","uitspraken_new",1);
    _21 := bat.reverse(_20);
    _22 := algebra.kdifference(_19,_21);
    _23 := bat.reverse(_22);
    _85 := algebra.join(_82,_23);
    _88 := algebra.markT(_85,3,0);
    _99 := bat.reverse(_88);
    _74:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",0,0@0:oid,87752@0);
    _26:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",2);
    _108 := algebra.kdifference(_74,_26);
    _110 := algebra.semijoin(_26,_74);
    _112 := algebra.kunion(_108,_110);
    _114 := algebra.leftjoin(_99,_112);
    _73:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",0,87752@0,nil:oid);
    _77 := algebra.kdifference(_73,_7);
    _79 := algebra.semijoin(_7,_73);
    _81 := algebra.kunion(_77,_79);
    _83 := algebra.kdifference(_81,_12);
    _86 := algebra.join(_83,_23);
    _91 := algebra.markT(_86,3,1);
    _102 := bat.reverse(_91);
    _75:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",0,87752@0,nil:oid);
    _109 := algebra.kdifference(_75,_26);
    _111 := algebra.semijoin(_26,_75);
    _113 := algebra.kunion(_109,_111);
    _115 := algebra.leftjoin(_102,_113);
    _9:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",1);
    _84 := algebra.kdifference(_9,_12);
    _87 := algebra.join(_84,_23);
    _94 := algebra.markT(_87,3,2);
    _104 := bat.reverse(_94);
    _29:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",1);
    _116 := algebra.leftjoin(_104,_29);
    _30 := mat.pack(_114,_115,_116);
    _107 := algebra.leftjoin(_104,_9);
    _106 := algebra.leftjoin(_102,_81);
    _105 := algebra.leftjoin(_99,_80);
exit _139;
    _148 := bat.new(nil:oid,nil:int);
barrier (_152,_153,_154) := bat.newIterator(_30);
    _156 := str.stringlength(_154);
    bat.insert(_148,_153,_156);
    redo (_152,_153,_154) := bat.hasMoreElements(_30);
exit (_152,_153,_154);
    _30 := nil:BAT;
    _31:bat[:oid,:int]  := _148;
barrier _142 := language.dataflow();
    _117 := bat.reverse(_85);
    _121 := algebra.markT(_117,3,0);
    _129 := bat.reverse(_121);
    _34:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken_new","uitspraak",0);
    _37:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken_new","uitspraak",2);
    _39 := algebra.kdifference(_34,_37);
    _40 := algebra.kunion(_39,_37);
    _41:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken_new","uitspraak",1);
    _43 := algebra.kunion(_40,_41);
    _135 := algebra.leftjoin(_129,_43);
    _119 := bat.reverse(_86);
    _124 := algebra.markT(_119,3,1);
    _130 := bat.reverse(_124);
    _137 := algebra.leftjoin(_130,_43);
    _120 := bat.reverse(_87);
    _127 := algebra.markT(_120,3,2);
    _131 := bat.reverse(_127);
    _138 := algebra.leftjoin(_131,_43);
    _44 := mat.pack(_135,_137,_138);
exit _142;
    _161 := bat.new(nil:oid,nil:int);
barrier (_163,_164,_165) := bat.newIterator(_44);
    _167 := str.stringlength(_165);
    bat.insert(_161,_164,_167);
    redo (_163,_164,_165) := bat.hasMoreElements(_44);
exit (_163,_164,_165);
    _44 := nil:BAT;
    _45:bat[:oid,:int]  := _161;
barrier _145 := language.dataflow();
    _24 := mat.pack(_105,_106,_107);
    _46:bat[:oid,:bit]  := batcalc.==(_31,_45);
exit _145;
    _47 := sql.resultSet(2,1,_24);
    sql.rsColumn(_47,"sys.uitspraken","id","int",32,0,_24);
    sql.rsColumn(_47,"sys.","=_length_uitspraak","boolean",1,0,_46);
    _57 := io.stdout();
    sql.exportResult(_57,_47);
end s1_1;

sql>explain select uitspraken.id,  length(uitspraken.uitspraak), length(uitspraken_new.uitspraak) from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id and length(uitspraken.uitspraak) <> length(uitspraken_new.uitspraak);
% .explain # table_name
% mal # name
% clob # type
% 0 # length
function user.s2_1{autoCommit=true}():void;
    _2 := sql.mvc();
barrier _251 := language.dataflow();
    _87:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",0,0@0:oid,87752@0);
    _25:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",2);
    _118 := algebra.kdifference(_87,_25);
    _120 := algebra.semijoin(_25,_87);
    _122 := algebra.kunion(_118,_120);
    _29:bat[:oid,:oid]  := sql.bind_dbat(_2,"sys","uitspraken",1);
    _30 := bat.reverse(_29);
    _125 := algebra.kdifference(_122,_30);
    _88:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",0,87752@0,nil:oid);
    _119 := algebra.kdifference(_88,_25);
    _121 := algebra.semijoin(_25,_88);
    _123 := algebra.kunion(_119,_121);
    _126 := algebra.kdifference(_123,_30);
    _28:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken","uitspraak",1);
    _127 := algebra.kdifference(_28,_30);
    _31 := mat.pack(_125,_126,_127);
    _9:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",1);
    _11:bat[:oid,:oid]  := sql.bind_dbat(_2,"sys","uitspraken",1);
    _12 := bat.reverse(_11);
    _97 := algebra.kdifference(_9,_12);
    _13:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken_new","id",0);
    _15:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken_new","id",2);
    _16 := algebra.kdifference(_13,_15);
    _17 := algebra.kunion(_16,_15);
    _18:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken_new","id",1);
    _19 := algebra.kunion(_17,_18);
    _20:bat[:oid,:oid]  := sql.bind_dbat(_2,"sys","uitspraken_new",1);
    _21 := bat.reverse(_20);
    _22 := algebra.kdifference(_19,_21);
    _23 := bat.reverse(_22);
    _100 := algebra.join(_97,_23);
    _107 := algebra.markT(_100,3,2);
    _117 := bat.reverse(_107);
    _86:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",0,87752@0,nil:oid);
    _7:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",2);
    _90 := algebra.kdifference(_86,_7);
    _92 := algebra.semijoin(_7,_86);
    _94 := algebra.kunion(_90,_92);
    _96 := algebra.kdifference(_94,_12);
    _99 := algebra.join(_96,_23);
    _104 := algebra.markT(_99,3,1);
    _115 := bat.reverse(_104);
    _84:bat[:oid,:int]  := sql.bind(_2,"sys","uitspraken","id",0,0@0:oid,87752@0);
    _89 := algebra.kdifference(_84,_7);
    _91 := algebra.semijoin(_7,_84);
    _93 := algebra.kunion(_89,_91);
    _95 := algebra.kdifference(_93,_12);
    _98 := algebra.join(_95,_23);
    _101 := algebra.markT(_98,3,0);
    _112 := bat.reverse(_101);
exit _251;
    _264 := bat.new(nil:oid,nil:int);
barrier (_268,_269,_270) := bat.newIterator(_31);
    _272 := str.stringlength(_270);
    bat.insert(_264,_269,_272);
    redo (_268,_269,_270) := bat.hasMoreElements(_31);
exit (_268,_269,_270);
    _31 := nil:BAT;
    _32:bat[:oid,:int]  := _264;
barrier _254 := language.dataflow();
    _35:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken_new","uitspraak",0);
    _38:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken_new","uitspraak",2);
    _40 := algebra.kdifference(_35,_38);
    _41 := algebra.kunion(_40,_38);
    _42:bat[:oid,:str]  := sql.bind(_2,"sys","uitspraken_new","uitspraak",1);
    _44 := algebra.kunion(_41,_42);
    _45:bat[:oid,:oid]  := sql.bind_dbat(_2,"sys","uitspraken_new",1);
    _46 := bat.reverse(_45);
    _47 := algebra.kdifference(_44,_46);
    _134 := bat.reverse(_100);
    _141 := algebra.markT(_134,3,2);
    _148 := bat.reverse(_141);
    _133 := bat.reverse(_99);
    _138 := algebra.markT(_133,3,1);
    _147 := bat.reverse(_138);
    _131 := bat.reverse(_98);
    _135 := algebra.markT(_131,3,0);
    _144 := bat.reverse(_135);
    _130 := algebra.leftjoin(_117,_32);
    _129 := algebra.leftjoin(_115,_32);
    _128 := algebra.leftjoin(_112,_32);
exit _254;
    _277 := bat.new(nil:oid,nil:int);
barrier (_279,_280,_281) := bat.newIterator(_47);
    _283 := str.stringlength(_281);
    bat.insert(_277,_280,_283);
    redo (_279,_280,_281) := bat.hasMoreElements(_47);
exit (_279,_280,_281);
    _47 := nil:BAT;
    _48:bat[:oid,:int]  := _277;
barrier _257 := language.dataflow();
    _153 := bat.mirror(_128);
    _150 := algebra.leftjoin(_144,_48);
    _156 := bat.mirror(_150);
    _159 := algebra.join(_153,_156);
    _165 := algebra.markT(_159,3,0);
    _168 := bat.reverse(_165);
    _171 := algebra.join(_168,_128);
    _162 := algebra.markH(_159,3,0);
    _175 := algebra.join(_162,_150);
    _179 := batcalc.!=(_171,_175);
    _184 := algebra.uselect(_179,true);
    _187 := bat.reverse(_184);
    _190 := algebra.join(_187,_162);
    _193 := bat.reverse(_190);
    _196 := algebra.semijoin(_112,_193);
    _202 := bat.reverse(_196);
    _206 := algebra.semijoin(_144,_193);
    _212 := algebra.join(_202,_206);
    _215 := algebra.markT(_212,3,0);
    _223 := bat.reverse(_215);
    _229 := algebra.leftjoin(_223,_122);
    _154 := bat.mirror(_129);
    _151 := algebra.leftjoin(_147,_48);
    _157 := bat.mirror(_151);
    _160 := algebra.join(_154,_157);
    _166 := algebra.markT(_160,3,1);
    _169 := bat.reverse(_166);
    _172 := algebra.join(_169,_129);
    _163 := algebra.markH(_160,3,1);
    _176 := algebra.join(_163,_151);
    _182 := batcalc.!=(_172,_176);
    _185 := algebra.uselect(_182,true);
    _188 := bat.reverse(_185);
    _191 := algebra.join(_188,_163);
    _194 := bat.reverse(_191);
    _198 := algebra.semijoin(_115,_194);
    _203 := bat.reverse(_198);
    _208 := algebra.semijoin(_147,_194);
    _213 := algebra.join(_203,_208);
    _219 := algebra.markT(_213,3,1);
    _224 := bat.reverse(_219);
    _230 := algebra.leftjoin(_224,_123);
    _155 := bat.mirror(_130);
    _152 := algebra.leftjoin(_148,_48);
    _158 := bat.mirror(_152);
    _161 := algebra.join(_155,_158);
    _167 := algebra.markT(_161,3,2);
    _170 := bat.reverse(_167);
    _174 := algebra.join(_170,_130);
    _164 := algebra.markH(_161,3,2);
    _177 := algebra.join(_164,_152);
    _183 := batcalc.!=(_174,_177);
    _186 := algebra.uselect(_183,true);
    _189 := bat.reverse(_186);
    _192 := algebra.join(_189,_164);
    _195 := bat.reverse(_192);
    _199 := algebra.semijoin(_117,_195);
    _204 := bat.reverse(_199);
    _209 := algebra.semijoin(_148,_195);
    _214 := algebra.join(_204,_209);
    _221 := algebra.markT(_214,3,2);
    _225 := bat.reverse(_221);
    _231 := algebra.leftjoin(_225,_28);
    _51 := mat.pack(_229,_230,_231);
    _228 := algebra.leftjoin(_225,_9);
    _227 := algebra.leftjoin(_224,_94);
    _226 := algebra.leftjoin(_223,_93);
exit _257;
    _288 := bat.new(nil:oid,nil:int);
barrier (_290,_291,_292) := bat.newIterator(_51);
    _294 := str.stringlength(_292);
    bat.insert(_288,_291,_294);
    redo (_290,_291,_292) := bat.hasMoreElements(_51);
exit (_290,_291,_292);
    _51 := nil:BAT;
    _52:bat[:oid,:int]  := _288;
barrier _260 := language.dataflow();
    _232 := bat.reverse(_212);
    _238 := algebra.markT(_232,3,0);
    _244 := bat.reverse(_238);
    _248 := algebra.leftjoin(_244,_44);
    _234 := bat.reverse(_213);
    _239 := algebra.markT(_234,3,1);
    _246 := bat.reverse(_239);
    _249 := algebra.leftjoin(_246,_44);
    _235 := bat.reverse(_214);
    _242 := algebra.markT(_235,3,2);
    _247 := bat.reverse(_242);
    _250 := algebra.leftjoin(_247,_44);
    _55 := mat.pack(_248,_249,_250);
exit _260;
    _299 := bat.new(nil:oid,nil:int);
barrier (_303,_304,_305) := bat.newIterator(_55);
    _307 := str.stringlength(_305);
    bat.insert(_299,_304,_307);
    redo (_303,_304,_305) := bat.hasMoreElements(_55);
exit (_303,_304,_305);
    _55 := nil:BAT;
    _56:bat[:oid,:int]  := _299;
    _50 := mat.pack(_226,_227,_228);
    _57 := sql.resultSet(3,1,_50);
    sql.rsColumn(_57,"sys.uitspraken","id","int",32,0,_50);
    sql.rsColumn(_57,"sys.","length_uitspraak","int",32,0,_52);
    sql.rsColumn(_57,"sys.","length_uitspraak","int",32,0,_56);
    _70 := io.stdout();
    sql.exportResult(_70,_57);
end s2_1;


CREATE TABLE "sys"."uitspraken" (
        "id"             int           NOT NULL,
        "ljn"            char(6)       NOT NULL,
        "gepubliceerd"   boolean       NOT NULL,
        "instantie"      varchar(63)   NOT NULL,
        "datum"          date          NOT NULL,
        "publicatie"     date,
        "zaaknummers"    varchar(100)  NOT NULL,
        "uitspraak"      CHARACTER LARGE OBJECT,
        "conclusie"      CHARACTER LARGE OBJECT,
        "zittingsplaats" varchar(16),
        "rechtsgebied"   varchar(24),
        "sector"         varchar(20),
        "soort"          varchar(32),
        "indicatie"      CHARACTER LARGE OBJECT,
        "kop"            CHARACTER LARGE OBJECT,
        CONSTRAINT "uitspraken_id_pkey" PRIMARY KEY ("id"),
        CONSTRAINT "uitspraken_ljn_unique" UNIQUE ("ljn")
);
sql>\d uitspraken_new 
CREATE TABLE "sys"."uitspraken_new" (
        "id"             int           NOT NULL,
        "ljn"            char(6)       NOT NULL,
        "gepubliceerd"   boolean       NOT NULL,
        "instantie"      varchar(63)   NOT NULL,
        "datum"          date          NOT NULL,
        "publicatie"     date,
        "zaaknummers"    varchar(100)  NOT NULL,
        "uitspraak"      CHARACTER LARGE OBJECT,
        "conclusie"      CHARACTER LARGE OBJECT,
        "zittingsplaats" varchar(16),
        "rechtsgebied"   varchar(24),
        "sector"         varchar(20),
        "soort"          varchar(32),
        "indicatie"      CHARACTER LARGE OBJECT,
        "kop"            CHARACTER LARGE OBJECT
);

Now I wonder if the fact that the unique constraint is not present in table 2 any reason for the performance to degrade in such way. (Most likely prefering the length equation?) Now I did try having the same constraints and that did not make any difference.

Facts about the tables; the uitspraken one contains about 2GB the _new one about 373 records, so virtually nothing. But now the database does crash:

mserver5: ../../../src/gdk/gdk_bbp.mx:2367: BBPfree: Assertion `b->P->sharecnt == 0' failed.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe32cf710 (LWP 15529)]
0x00007ffff4839445 in raise () from /lib/libc.so.6
(gdb) bt
#0  0x00007ffff4839445 in raise () from /lib/libc.so.6
#1  0x00007ffff483a941 in abort () from /lib/libc.so.6
#2  0x00007ffff48326a0 in __assert_fail () from /lib/libc.so.6
#3  0x00007ffff6aa6846 in BBPfree (b=0x15a31d8, calledFrom=0x7ffff7114cd6 "BBPtrim") at ../../../src/gdk/gdk_bbp.mx:2367
#4  0x00007ffff6aa8f47 in BBPtrim (memtarget=0, vmtarget=0) at ../../../src/gdk/gdk_bbp.mx:2764
#5  0x00007ffff6c29b75 in GDKmemchk (memchk=1, vmchk=0) at ../../../src/gdk/gdk_utils.mx:714
#6  0x00007ffff6c2a0c7 in GDKmallocmax (size=2320, maxsize=0x7fffe32ce128, emergency=0) at ../../../src/gdk/gdk_utils.mx:1105
#7  0x00007ffff6c2a364 in GDKmalloc (size=2316) at ../../../src/gdk/gdk_utils.mx:1131
#8  0x00007ffff6c2ae5d in GDKstrdup (
    s=0x7ffd7c1ba618 "gewezen op het beroep in cassatie van X te Z tegen de uitspraak van het Gerechtshof te Arnhem van 19 mei 1995 betreffende na te melden aan hem voor het jaar 1989 opgelegde aanslag in de zuiveringslast"...) at ../../../src/gdk/gdk_utils.mx:1307
#9  0x00007ffff6ff5cb0 in VALinit (d=0x15b4ad8, tpe=13, s=0x7ffd7c1ba618) at ../../../src/gdk/gdk_value.mx:192
#10 0x00007fffe6ff2dd8 in CHPbunHasMoreElements (cntxt=0x605878, mb=0x1001028, stk=0x15b3958, pci=0xd7fe98) at ../../../../src/modules/mal/chopper.mx:276
#11 0x00007ffff7ac5a40 in runMALsequence (cntxt=0x605878, mb=0x1001028, startpc=1, stoppc=0, stk=0x15b3958, env=0x0, pcicaller=0x0)
    at ../../../src/mal/mal_interpreter.mx:2044
#12 0x00007ffff7abb833 in callMAL (cntxt=0x605878, mb=0x1001028, env=0x7fffe32cec38, argv=0x7fffe32cec80, debug=0 '\000')
    at ../../../src/mal/mal_interpreter.mx:435
#13 0x00007fffe42930d7 in SQLexecutePrepared (c=0x605878, be=0xb10f48, q=0x158afe8) at ../../../../src/backends/monet5/sql_scenario.mx:1454
#14 0x00007fffe4293356 in SQLengineIntern (c=0x605878, be=0xb10f48) at ../../../../src/backends/monet5/sql_scenario.mx:1507
#15 0x00007fffe4293891 in SQLengine (c=0x605878) at ../../../../src/backends/monet5/sql_scenario.mx:1617
#16 0x00007ffff7b05226 in runPhase (c=0x605878, phase=4) at ../../../src/mal/mal_scenario.mx:604
#17 0x00007ffff7b053fd in runScenarioBody (c=0x605878) at ../../../src/mal/mal_scenario.mx:655
#18 0x00007ffff7b055e5 in runScenario (c=0x605878) at ../../../src/mal/mal_scenario.mx:682
#19 0x00007ffff7ab931f in MSserveClient (dummy=0x605878) at ../../../src/mal/mal_session.mx:473
#20 0x00007ffff57a9547 in start_thread () from /lib/libpthread.so.0
#21 0x00007ffff48db28d in clone () from /lib/libc.so.6


Reproducible: Always




MonetDB server v5.21.0 (64-bit), based on kernel v1.39.0 (64-bit oids)
Copyright (c) 1993-July 2008 CWI
Copyright (c) August 2008-2010 MonetDB B.V., all rights reserved
Visit http://monetdb.cwi.nl/ for further information
Found 3.9GiB available memory, 2 available cpu cores
Configured for prefix: /opt/monetdb-testing
Libraries:
  libpcre: 8.02 2010-03-19 (compiled with 8.02)
  openssl: OpenSSL 0.9.8o 01 Jun 2010 (compiled with OpenSSL 0.9.8o 01 Jun 2010)
  libxml2: 2.7.7 (compiled with 2.7.7)
Compiled by: skinkie@openkvk (x86_64-unknown-linux-gnu)
Compilation: gcc -Wall -Wextra -fno-strict-aliasing -g  -Werror-implicit-function-declaration -Werror -Wpointer-arith -Wdeclaration-after-statement -Wundef -Wp,-D_FORTIFY_SOURCE=2
Linking    : /usr/x86_64-pc-linux-gnu/bin/ld -IPA -m elf_x86_64 

(obviously I can upgrade again ;)
Comment 1 Fabian Groffen 2010-07-22 19:20:04 CEST
how many bugs did you report in total in this epistle?
Comment 2 Stefan de Konink 2010-07-22 19:24:13 CEST
(In reply to comment #1)
> how many bugs did you report in total in this epistle?

Just one Fabian. I was just extremely verbose, so * cannot blame me about being unclear. And not providing enough information. As you can see in the plans, it is a comparison between two queries. Where one never finishes.
Comment 3 Fabian Groffen 2010-07-22 19:27:07 CEST
how about the segfault then?
Comment 4 Stefan de Konink 2010-07-22 19:30:37 CEST
(In reply to comment #3)
> how about the segfault then?

The segfault is the same bug, with a constrained second table. I expect that the same behavior (eventually) would show up if I didn't cancel the second query. I just didn't want to wait longer than 76ms for my results.
Comment 5 Stefan de Konink 2010-07-22 19:36:47 CEST
MonetDB server v5.21.0 (64-bit), based on kernel v1.39.0 (64-bit oids)
Not released
Copyright (c) 1993-July 2008 CWI
Copyright (c) August 2008-2010 MonetDB B.V., all rights reserved
Visit http://monetdb.cwi.nl/ for further information
Found 3.9GiB available memory, 2 available cpu cores
Configured for prefix: /opt/monetdb-testing
Libraries:
  libpcre: 8.02 2010-03-19 (compiled with 8.02)
  openssl: OpenSSL 0.9.8o 01 Jun 2010 (compiled with OpenSSL 0.9.8o 01 Jun 2010)
  libxml2: 2.7.7 (compiled with 2.7.7)
Compiled by: skinkie@openkvk (x86_64-unknown-linux-gnu)
Compilation: gcc -Wall -Wextra -fno-strict-aliasing -g  -Werror-implicit-function-declaration -Werror -Wpointer-arith -Wdeclaration-after-statement -Wundef -Wp,-D_FORTIFY_SOURCE=2
Linking    : /usr/x86_64-pc-linux-gnu/bin/ld -IPA -m elf_x86_64

(Latest HG, same behavior)
Comment 6 Stefan Manegold cwiconfidential 2010-07-22 19:50:25 CEST
The "poor performance" is apparently due to missing bulk implementation of function str.stringlength() --- or at least the SQL compiler (and or what ever optimizer is in charge) does not know about it.

I cannot comment about the rest (if there is any at all), as "clearity" cannot simply be achieved by "verboseness"; "conciseness" usually serves better purposes ...
Comment 7 Stefan Manegold cwiconfidential 2010-07-22 19:53:17 CEST
Oh, the assertion (obviously) looks similar to the one reported in bug 2607 "GDK: gdk_bbp.c:2257: BBPfree: Assertion `b->P->sharecnt == 0' failed".
Comment 8 Stefan de Konink 2010-07-22 20:02:30 CEST
(In reply to comment #6)
> The "poor performance" is apparently due to missing bulk implementation of
> function str.stringlength() --- or at least the SQL compiler (and or what ever
> optimizer is in charge) does not know about it.

Why would it need a bulk stringlength operation? The first query finishes in 76ms...
Comment 9 Stefan Manegold cwiconfidential 2010-07-22 20:08:31 CEST
you tell me how often SQL length() resp. MAL str.stringlength needs to be called either of your --- depends on you actual data size, value distribution, selection- and join selectivity, etc. and I don't know that --- basically, the answer to this question should answer your question.
Comment 10 Stefan de Konink 2010-07-22 20:15:33 CEST
(In reply to comment #9)
> you tell me how often SQL length() resp. MAL str.stringlength needs to be
> called either of your --- depends on you actual data size, value distribution,
> selection- and join selectivity, etc. and I don't know that --- basically, the
> answer to this question should answer your question.

The amount of records match the resultset of the first operation? If the length(...) = length(...) is preferred over the equijoin while the number of values of combined equijoins is lower and no sql function is used...

How is it possible that the first query that puts the same clause in the select part takes 76ms, and the second query that filters on the where clause of the first query plus the second query breaks?
Comment 11 Stefan Manegold cwiconfidential 2010-07-22 20:27:58 CEST
From the algebra (PLAN) and MAL (EXPLAIN) plans you provided, I read that for the first query, length is called twice for each result tuple, while for the second query length is called twice for each result tuple plus once for each tuple in table uitspraken plus once for each tuple in table uitspraken_new.

The difference is one reasons for exection time differences between the two queries --- what ever they might be ...
Comment 12 Stefan de Konink 2010-07-22 20:35:13 CEST
(In reply to comment #11)
> The difference is one reasons for exection time differences between the two
> queries --- what ever they might be ...

So pragmatically, is my assumption, that the 2 length-functions should exclusively be called for the rows that are selected by the id = id, correct?

If that doesn't hold, I probably am missing a fundamental thing.
Comment 13 Stefan Manegold cwiconfidential 2010-07-22 21:43:12 CEST
Your assumption is reasonable in theory. The details are much more complicated in practice. The problem is usually referred to as database query optimization and has been proven to be NP-hard ("even" in theory).
Comment 14 Stefan Manegold cwiconfidential 2010-07-22 21:58:49 CEST
By the way, I would appreciate if you would --- at some point in time --- not mind sharing with us how long the second query actually runs. Only then, we could properly assess the severity of the problem. With all respect, a statement like "doesn't finish fast enough" does not help us much further.
With the first query finishing in 76 ms, killing the second query after 76 ms is everything but an indication of "poor performance" to me.

Also, could you please explain a bit more clearly than "But now the database does crash", in which case the assertion occurs?
When staring the server?
When running the (which?) query?
When running the (which?) query after restarting the server?

Please not also, that bug 2607 mentions a hanging server in relation with a similar assertion as reported here.
Comment 15 Stefan de Konink 2010-07-22 23:20:47 CEST
(In reply to comment #14)
> By the way, I would appreciate if you would --- at some point in time --- not
> mind sharing with us how long the second query actually runs.

I have no clue how long I actually takes. I actually thought waiting > 5 minutes was a proper indication to file a bug if I can gather the same information in 76ms.

But the actual point is now, that when I remove the constraints I actually end up in the same assertion, that I didn't see before. And this was about ~3 minutes. So I wonder now if I should reload the secondary table without the primary key/unique in the first place to get the same result.

> Only then, we
> could properly assess the severity of the problem. With all respect, a
> statement like "doesn't finish fast enough" does not help us much further.

With all respect;
If the following query does finish in 77ms, I truly feel that I showed by both plans enough information was provided to unfold an issue in the plan generation.

plan select x from (select uitspraken.id as x, length(uitspraken.uitspraak)=length(uitspraken_new.uitspraak) as y from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id) as z where z.y = false;
% .plan # table_name
% rel # name
% clob # type
% 170 # length
project (
| select (
| | project (
| | | join (
| | | | table(sys.uitspraken) [ uitspraken.id NOT NULL, uitspraken.uitspraak, uitspraken.%TID% NOT NULL ],
| | | | table(sys.uitspraken_new) [ uitspraken_new.id NOT NULL, uitspraken_new.uitspraak, uitspraken_new.%TID% NOT NULL ]
| | | ) [ uitspraken.id NOT NULL = uitspraken_new.id NOT NULL ]
| | ) [ uitspraken.id NOT NULL as z.x, =(length(uitspraken.uitspraak), length(uitspraken_new.uitspraak)) as z.y, uitspraken.%TID% NOT NULL, uitspraken_new.%TID% NOT NULL ]
| ) [ z.y = false ]
) [ z.x NOT NULL ]


> Also, could you please explain a bit more clearly than "But now the database
> does crash", in which case the assertion occurs?

Currently in the second provided query.
select uitspraken.id,  length(uitspraken.uitspraak),
length(uitspraken_new.uitspraak) from uitspraken, uitspraken_new where
uitspraken.id = uitspraken_new.id and length(uitspraken.uitspraak) <>
length(uitspraken_new.uitspraak);

> When staring the server?

Before running the query.

> Please not also, that bug 2607 mentions a hanging server in relation with a
> similar assertion as reported here.

Server does not hang.
Comment 16 Stefan Manegold cwiconfidential 2010-07-26 18:20:26 CEST
In a different context I just ran a query that perform 100 M (100000000) legth() (resp. str.stringlength()) call in about 100 second, i.e., one per microsecond
(using on optimized build of the Jun2010-SP1 release on a 2.4 GB Core2Quad).
Hence, I doubt that the mal-iterated (as opposed to bulk) str.stringlength() is a significant performance problem.
I suspect (now more than already indicated before) that the "second query" reported here just "happens to trigger" a situation that leads to the assertion and/or hanging server (while processing that query) as reported in bug 2607 (see details there).
Comment 17 Stefan de Konink 2010-07-26 18:27:20 CEST
(In reply to comment #16)
> I suspect (now more than already indicated before) that the "second query"
> reported here just "happens to trigger" a situation that leads to the assertion
> and/or hanging server (while processing that query) as reported in bug 2607
> (see details there).

Is the actual 'hang' to pin-point sowhere in the mal plan? Or is it not that 'fixed'. The hang might eat CPU time, ok, can live with that. But wasn't the idea of optimizers to always execute the 'same' kind of query; hence my rewrite of the query should result in the same 'failing' query?
Comment 18 Martin Kersten cwiconfidential 2010-07-27 20:18:34 CEST
The multiplex version of the SQL stringlength operator was missing. It has been added to the kernel.
Comment 19 Stefan de Konink 2010-07-30 16:53:23 CEST
(In reply to comment #18)
> The multiplex version of the SQL stringlength operator was missing. It has been
> added to the kernel.

I would like to confirm that this indeed has 'fixed' the issue, making it possible to execute the query.

sql>select uitspraken.id from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id and  length(uitspraken.uitspraak)<>length(uitspraken_new.uitspraak);
+--------+
| id     |
+========+
| 390815 |
| 390904 |
| 385703 |
| 390984 |
| 386513 |
| 390801 |
| 390658 |
| 373523 |
+--------+
8 tuples (32.122s)
(hot: 10s)

But having already elaborated in the initial issue, it seems the wrong choice is made because the following query results within 100ms.


sql>select x from (select uitspraken.id as x, length(uitspraken.uitspraak)=length(uitspraken_new.uitspraak) as y from uitspraken, uitspraken_new where uitspraken.id = uitspraken_new.id) as z where z.y = false;
+--------+
| x      |
+========+
| 390815 |
| 390904 |
| 385703 |
| 390984 |
| 386513 |
| 390801 |
| 390658 |
| 373523 |
+--------+
8 tuples (64.491ms)
Comment 20 Stefan Manegold cwiconfidential 2010-08-02 11:47:21 CEST
To clarify, the improvement of bulk over iterated length() (str.stringLength()), i.e., of http://dev.monetdb.org/hg/MonetDB/rev/b6c69da89ab1 is a factor, i.e., for my 100000000 tuple test, execution time went down from 100 secs to 20 secs.

Note also that http://dev.monetdb.org/hg/MonetDB/rev/3b40c80c9172 fixed a deadlock that I still suspect to be the reason why the second query did (IMHO --- was indeed never tested let alone confirmed) hang.

Finally, the "choice" how to translate and implement single-column vs. multi-columns joins in MonetDB is inherent in the MonetDB architecture; hence, unless the whole MonetDB architecture is considered a "wrong choice", I cannot detect any wrong choice, here. More complex queries often ten to take more time to execute than less complex ones.
Comment 21 Stefan de Konink 2010-08-02 14:53:13 CEST
(In reply to comment #20)
> Finally, the "choice" how to translate and implement single-column vs.
> multi-columns joins in MonetDB is inherent in the MonetDB architecture; hence,
> unless the whole MonetDB architecture is considered a "wrong choice", I cannot
> detect any wrong choice, here. More complex queries often ten to take more time
> to execute than less complex ones.

I think how Niels explains it, that a push up of the length function should occur. I mailed him some examples where the complete rewrite takes place:


create table lengthequijoin (id integer, a varchar(10));
create table lengthequijoin_to (id integer, a varchar(10));

plan select b.id from lengthequijoin as b, lengthequijoin_to as c where b.id = c.id and length(c.a) <> length(b.a);

Ik denk dat die hem in principe al laat zien... maar het bizarre is dat deze:

plan select x.d from (select b.id as d, b.a as e, c.a as f from lengthequijoin as b, lengthequijoin_to as c where b.id = c.id) as x where length(x.e) <>
length(x.f);

Dus wel 'terug' wordt geprojecteerd in de vorige, maar deze niet:

plan select x.d from (select b.id as d, length(b.a) <> length(c.a) as e from lengthequijoin as b, lengthequijoin_to as c where b.id = c.id) as x where x.e = true;
Comment 22 Fabian Groffen 2010-10-28 13:27:25 CEST
this is a feature request for a faster execution
Comment 23 Sjoerd Mullender cwiconfidential 2011-03-28 17:36:33 CEST
The Mar2011 version has been released.
Comment 24 Sjoerd Mullender cwiconfidential 2011-07-29 11:00:07 CEST
Apr2011-SP2 has been released.
Comment 25 Sjoerd Mullender cwiconfidential 2011-09-16 15:10:41 CEST
The Aug2011 version has been released.
Comment 26 Sjoerd Mullender cwiconfidential 2012-08-24 14:56:01 CEST
Jul2012-SP1 has been released.