[Maria-developers] RQG crashes tokudb due to unexpected storage engine API call sequence
![](https://secure.gravatar.com/avatar/2f5785186f96abd19947fcbee8fbb51b.jpg?s=120&d=mm&r=g)
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
![](https://secure.gravatar.com/avatar/39b623a1559cf9c69ac3d9d4fb44e7fe.jpg?s=120&d=mm&r=g)
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
![](https://secure.gravatar.com/avatar/2f5785186f96abd19947fcbee8fbb51b.jpg?s=120&d=mm&r=g)
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
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