[Maria-developers] RQG crashes tokudb due to unexpected storage engine API call sequence
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? Thanks Rich Prohaska
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
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
participants (2)
-
Rich Prohaska -
Sergei Golubchik