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@mariadb.org> 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