maria-developers team mailing list archive

[Rich Prohaska <prohaska@xxxxxxxxxxx>]

When I run this RQG test against a debug build of mariadb-5.5.34:

./runall.pl --grammar=conf/optimizer/optimizer_subquery_no_outer_join.yy
--duration=300 --queries=100000000 --threads=1
--basedir=/home/prohaska/mariadb-5.5.34-install
--vardir=/home/prohaska/vardir.mariadb.5534.1 --mask-level=0 --mask=0
--seed=1 --mysqld=--general_log --sqltrace
--mysqld=--plugin-load=ha_tokudb.so --mysqld=--loose-tokudb-debug=60
--engine=tokudb

TokuDB hits this assert:

db.cc", line=4684, caller_errno=0) at
/home/prohaska/mariadb-5.5.34/storage/tokudb/ft-index/src/ydb.cc:2236
# 2013-12-05T12:52:47 #9  0x00007f3af7839463 in toku_hton_assert_fail
(expr_as_string=0x7f3af796655c "r==0", fun=0x7f3af796b234 "index_end",
file=0x7f3af79662a0
"/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc", line=4684,
caller_errno=0) at
/home/prohaska/mariadb-5.5.34/storage/tokudb/hatoku_hton.cc:193
# 2013-12-05T12:52:47 #10 0x00007f3af7821ec6 in ha_tokudb::index_end
(this=0x7f3b0352d078) at
/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4684
# 2013-12-05T12:52:47 #11 0x00000000005a43ab in handler::ha_index_end
(this=0x7f3b0352d078) at /home/prohaska/mariadb-5.5.34/sql/handler.h:1867
# 2013-12-05T12:52:47 #12 0x00000000005eadaf in
handler::ha_index_or_rnd_end (this=0x7f3b0352d078) at
/home/prohaska/mariadb-5.5.34/sql/handler.h:1911
# 2013-12-05T12:52:47 #13 0x000000000065293c in st_join_table::cleanup
(this=0x7f3b03517a70) at
/home/prohaska/mariadb-5.5.34/sql/sql_select.cc:10368
# 2013-12-05T12:52:47 #14 0x0000000000653677 in JOIN::cleanup
(this=0x7f3ae1cd95e0, full=true) at
/home/prohaska/mariadb-5.5.34/sql/sql_select.cc:10770
# 2013-12-05T12:52:47 #15 0x0000000000640341 in JOIN::destroy
(this=0x7f3ae1cd95e0) at
/home/prohaska/mariadb-5.5.34/sql/sql_select.cc:2918
# 2013-12-05T12:52:47 #16 0x00000000006b9efb in st_select_lex::cleanup
(this=0x7f3ae1c6c630) at /home/prohaska/mariadb-5.5.34/sql/sql_union.cc:995
# 2013-12-05T12:52:47 #17 0x00000000006b9ad1 in st_select_lex_unit::cleanup
(this=0x7f3ae1c6c998) at /home/prohaska/mariadb-5.5.34/sql/sql_union.cc:860
# 2013-12-05T12:52:47 #18 0x00000000006b9f55 in st_select_lex::cleanup
(this=0x7f3b0df09a50) at /home/prohaska/mariadb-5.5.34/sql/sql_union.cc:1002
# 2013-12-05T12:52:47 #19 0x00000000006b9ad1 in st_select_lex_unit::cleanup
(this=0x7f3b0df09378) at /home/prohaska/mariadb-5.5.34/sql/sql_union.cc:860
# 2013-12-05T12:52:47 #20 0x000000000061064e in mysql_execute_command
(thd=0x7f3b0df06060) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:4578
# 2013-12-05T12:52:47 #21 0x00000000006132be in mysql_parse
(thd=0x7f3b0df06060, rawbuf=0x7f3b03528078 "EXPLAIN EXTENDED SELECT
 COUNT(  table1 . `pk` ) AS field1 FROM ( (  SELECT   SUBQUERY1_t1 . * FROM
( C AS SUBQUERY1_t1 STRAIGHT_JOIN ( C AS SUBQUERY1_t2 INNER JOIN CC AS
SUBQUERY1_t3 ON (SUBQUERY1_t3 . `pk` = SUBQUERY1_t2 . `pk`  ) ) ON
(SUBQUERY1_t3 . `col_int_key` = SUBQUERY1_t2 . `col_int_key`  ) )  ) AS
table1 STRAIGHT_JOIN ( ( C AS table2 INNER JOIN (  SELECT   SUBQUERY2_t1 .
* FROM ( D AS SUBQUERY2_t1 STRAIGHT_JOIN B AS SUBQUERY2_t2 ON (SUBQUERY2_t2
. `pk` = SUBQUERY2_t1 . `pk`  ) )  ) AS table3 ON (table3 .
`col_varchar_key` = table2 . `col_varchar_key`  ) ) ) ON (table3 .
`col_varchar_key` = table2 . `col_varchar_key`  ) ) WHERE (  table2 .
`col_int_key` = ( SELECT 9 FROM DUAL ) ) OR ( table1 . `col_int_key` = 144
AND table1 . `col_varchar_key` = 'l' )  HAVING ((field1 > 'z' AND  ( 'b',
'x' )  IN ( SELECT   SUBQUERY4_t1 . `col_varchar_key` AS SUBQUERY4_field1 ,
SUBQUERY4_t1 . `col_v

Caused because the transaction that created the cursor that we are trying
to close was previously committed:

2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6233:just
created stmt (nil) 0x7f3b034c4c00
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6259:ha_tokudb::external_lock
cmd=0 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6259:ha_tokudb::external_lock
cmd=0 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6259:ha_tokudb::external_lock
cmd=0 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6259:ha_tokudb::external_lock
cmd=0 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6259:ha_tokudb::external_lock
cmd=0 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6259:ha_tokudb::external_lock
cmd=0 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6328:external_lock:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:5954:ha_tokudb::info
0x7f3b0352d078 18 20
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:6089:info:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:7316:ha_tokudb::scan_time
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:7316:ha_tokudb::scan_time
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:406:ha_tokudb::index_flags
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:7361:ha_tokudb::read_time
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:406:ha_tokudb::index_flags
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4606:ha_tokudb::index_init
0x7f3b0352d078 5
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4672:index_init:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4926:ha_tokudb::index_read
0x7f3b0352d078 find 0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:2936:ha_tokudb::pack_key
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:2996:ha_tokudb::pack_ext_key
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4709:ha_tokudb::handle_cursor_error
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4720:handle_cursor_error:return
120
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:5016:error:120:0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:5022:index_read:return
120
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/hatoku_hton.cc:689:tokudb_commit
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/hatoku_hton.cc:697:commit
0 0x7f3b034c4c00
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/hatoku_hton.cc:714:tokudb_commit:return
0
2073:/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4679:ha_tokudb::index_end
0x7f3b0352d078
131205 20:52:40 [ERROR] TokuDB:  toku_c_close: Transaction cannot do work
when child exists

/home/prohaska/mariadb-5.5.34/storage/tokudb/ha_tokudb.cc:4684 index_end:
Assertion `Handlerton: r==0 ' failed (errno=0)




On Thu, Dec 5, 2013 at 12:02 PM, Sergei Golubchik <serg@xxxxxxxxxxx> wrote:

> Hi, Rich!
>
> On Dec 05, Rich Prohaska wrote:
> > We are debugging a crash induced by RQG in the tokudb storage engine.
> The
> > cause of the crash is a mismatch in assumptions about the sequence of
> > storage engine API calls.
> >
> > We see:
> >
> > tokudb::external_lock creates a txn
> > tokudb::index_init creates a cursor on a index db with the txn
> > tokudb::index_read use the cursor to try to read a row, and returns an
> error
> > tokudb_commit commits the txn (called from sql_parse.cc:4584)
> >
> > tokudb::index_end tries to close the cursor and crashes since the txn has
> > been committed. (called from the unit.cleanup() call at
> sql_parse.cc:4592)
> >
> > The current tokudb software does not expect the commit to occur before
> > index_end is called.  Is this assumption correct?  Since mariadb (and i
> > suspect mysql) does this, it appears that the storage engine should
> expect
> > commit before index_end.  Any comments?
>
> You've provided too little information, so off the top of my head
> I'd say that what you see is a bug and that commit should not happen in
> the middle of the index scan.
>
> What SQL statement causes it?
>
> Regards,
> Sergei
>
>