10.4 commit ea912d1605b463a16a0c186bf10e61c4af519439 compiled with debug
|
storage/innobase/lock/lock0lock.cc:6317: my_bool lock_table_locks_lookup(rw_trx_hash_element_t*, const dict_table_t*): Assertion `!dict_index_is_online_ddl(lock->index) || lock->index->is_primary()' failed.
|
...
|
/home/mleich/Server_bin/10.4_debug/bin/mysqld(+0xdefd97)[0x559c5fe90d97]
|
lock/lock0lock.cc:6319(lock_table_locks_lookup(rw_trx_hash_element_t*, dict_table_t const*))[0x559c5fe7a37e]
|
/home/mleich/Server_bin/10.4_debug/bin/mysqld(_ZN7handler15ha_delete_tableEPKc+0x3c)[0x559c5fc2b712]
|
/home/mleich/Server_bin/10.4_debug/bin/mysqld(_Z15ha_delete_tableP3THDP10handlertonPKcPK25st_mysql_const_lex_stringS7_b+0x16f)[0x559c5fc2475e]
|
mysys/lf_hash.c:127(l_find)[0x559c5f9a63a5]
|
mysys/lf_hash.c:519(lf_hash_iterate)[0x559c5f9bc14e]
|
/home/mleich/Server_bin/10.4_debug/bin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x894)[0x559c5fa531ce]
|
/home/mleich/Server_bin/10.4_debug/bin/mysqld(_Z21mysql_execute_commandP3THD+0xa2f2)[0x559c5f8d23b7]
|
include/trx0sys.h:753(rw_trx_hash_t::iterate(trx_t*, char (*)(void*, void*), void*))[0x559c5f8d786d]
|
lock/lock0lock.cc:6358(lock_table_has_locks(dict_table_t const*))[0x559c5f8c3e28]
|
row/row0mysql.cc:3550(row_drop_table_for_mysql(char const*, trx_t*, enum_sql_command, bool, bool))[0x559c5f8c25c9]
|
/home/mleich/Server_bin/10.4_debug/bin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1e6)[0x559c5fa49bf8]
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
|
#1 0x00007ff08c2cf801 in __GI_abort () at abort.c:79
|
#2 0x00007ff08c2bf39a in __assert_fail_base (fmt=0x7ff08c4467d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x559c608bb1b0 "!dict_index_is_online_ddl(lock->index) || lock->index->is_primary()",
|
file=file@entry=0x559c608b8918 "/home/mleich/10.4/storage/innobase/lock/lock0lock.cc", line=line@entry=6317,
|
function=function@entry=0x559c608bfb40 <lock_table_locks_lookup(rw_trx_hash_element_t*, dict_table_t const*)::__PRETTY_FUNCTION__> "my_bool lock_table_locks_lookup(rw_trx_hash_element_t*, const dict_table_t*)") at assert.c:92
|
#3 0x00007ff08c2bf412 in __GI___assert_fail (assertion=0x559c608bb1b0 "!dict_index_is_online_ddl(lock->index) || lock->index->is_primary()", file=0x559c608b8918 "/home/mleich/10.4/storage/innobase/lock/lock0lock.cc", line=6317,
|
function=0x559c608bfb40 <lock_table_locks_lookup(rw_trx_hash_element_t*, dict_table_t const*)::__PRETTY_FUNCTION__> "my_bool lock_table_locks_lookup(rw_trx_hash_element_t*, const dict_table_t*)") at assert.c:101
|
#4 0x0000559c5ff25bd6 in lock_table_locks_lookup (element=0x7fefe001b988, table=0x7fefec064460) at /home/mleich/10.4/storage/innobase/lock/lock0lock.cc:6317
|
#5 0x0000559c5ff29a62 in rw_trx_hash_t::debug_iterator (element=0x7fefe001b988, arg=0x7ff06c05e7e0) at /home/mleich/10.4/storage/innobase/include/trx0sys.h:535
|
#6 0x0000559c60583752 in l_find (head=0x7fefd4020ec8, cs=0x0, hashnr=0, key=0x7ff06c05e7e0 "sX\362_\234U", keylen=0, cursor=0x7ff06c05e780, pins=0x559c62357498,
|
callback=0x559c5ff299d9 <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>) at /home/mleich/10.4/mysys/lf_hash.c:127
|
#7 0x0000559c60584442 in lf_hash_iterate (hash=0x559c61189fc0 <trx_sys+2496>, pins=0x559c62357498, action=0x559c5ff299d9 <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>, argument=0x7ff06c05e7e0)
|
at /home/mleich/10.4/mysys/lf_hash.c:519
|
#8 0x0000559c5ff29e4d in rw_trx_hash_t::iterate (this=0x559c61189fc0 <trx_sys+2496>, caller_trx=0x7ff0888ce5e0, action=0x559c5ff299d9 <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>, argument=0x7ff06c05e7e0)
|
at /home/mleich/10.4/storage/innobase/include/trx0sys.h:753
|
#9 0x0000559c5ff29e98 in rw_trx_hash_t::iterate (this=0x559c61189fc0 <trx_sys+2496>, action=0x559c5ff25873 <lock_table_locks_lookup(rw_trx_hash_element_t*, dict_table_t const*)>, argument=0x7fefec064460)
|
at /home/mleich/10.4/storage/innobase/include/trx0sys.h:762
|
#10 0x0000559c5ff25e13 in lock_table_has_locks (table=0x7fefec064460) at /home/mleich/10.4/storage/innobase/lock/lock0lock.cc:6351
|
#11 0x0000559c60017dcc in row_drop_table_for_mysql (name=0x7ff06c05ef70 "test/#sql2-2cff-14", trx=0x7ff0888d0830, sqlcom=SQLCOM_ALTER_TABLE, create_failed=false, nonatomic=true) at /home/mleich/10.4/storage/innobase/row/row0mysql.cc:3550
|
#12 0x0000559c5fe90d97 in ha_innobase::delete_table (this=0x7fefe8014ed8, name=0x7ff06c060a40 "./test/#sql2-2cff-14", sqlcom=SQLCOM_ALTER_TABLE) at /home/mleich/10.4/storage/innobase/handler/ha_innodb.cc:13133
|
#13 0x0000559c5fe7a37e in ha_innobase::delete_table (this=0x7fefe8014ed8, name=0x7ff06c060a40 "./test/#sql2-2cff-14") at /home/mleich/10.4/storage/innobase/handler/ha_innodb.cc:13258
|
#14 0x0000559c5fc2b712 in handler::ha_delete_table (this=0x7fefe8014ed8, name=0x7ff06c060a40 "./test/#sql2-2cff-14") at /home/mleich/10.4/sql/handler.cc:4708
|
#15 0x0000559c5fc2475e in ha_delete_table (thd=0x7fefe8000ce8, table_type=0x559c62087598, path=0x7ff06c060a40 "./test/#sql2-2cff-14", db=0x7ff06c062750, alias=0x7ff06c060e40, generate_warning=false) at /home/mleich/10.4/sql/handler.cc:2598
|
#16 0x0000559c5f9a63a5 in quick_rm_table (thd=0x7fefe8000ce8, base=0x559c62087598, db=0x7ff06c062750, table_name=0x7ff06c060e40, flags=3, table_path=0x0) at /home/mleich/10.4/sql/sql_table.cc:2767
|
#17 0x0000559c5f9bc14e in mysql_alter_table (thd=0x7fefe8000ce8, new_db=0x7fefe80054a8, new_name=0x7fefe80058b0, create_info=0x7ff06c063320, table_list=0x7fefe80115d0, alter_info=0x7ff06c063260, order_num=0, order=0x0, ignore=false)
|
at /home/mleich/10.4/sql/sql_table.cc:10396
|
#18 0x0000559c5fa531ce in Sql_cmd_alter_table::execute (this=0x7fefe8011db8, thd=0x7fefe8000ce8) at /home/mleich/10.4/sql/sql_alter.cc:514
|
#19 0x0000559c5f8d23b7 in mysql_execute_command (thd=0x7fefe8000ce8) at /home/mleich/10.4/sql/sql_parse.cc:6101
|
#20 0x0000559c5f8d786d in mysql_parse (thd=0x7fefe8000ce8, rawbuf=0x7fefe8011470 "ALTER TABLE t1 MODIFY col2 INT, ALGORITHM = DEFAULT /* E_R Thread2 QNO 260 CON_ID 20 */", length=88, parser_state=0x7ff06c0645a0, is_com_multi=false,
|
is_next_command=false) at /home/mleich/10.4/sql/sql_parse.cc:7900
|
#21 0x0000559c5f8c3e28 in dispatch_command (command=COM_QUERY, thd=0x7fefe8000ce8, packet=0x7fefe8008119 " ALTER TABLE t1 MODIFY col2 INT, ALGORITHM = DEFAULT /* E_R Thread2 QNO 260 CON_ID 20 */ ", packet_length=90, is_com_multi=false,
|
is_next_command=false) at /home/mleich/10.4/sql/sql_parse.cc:1841
|
#22 0x0000559c5f8c25c9 in do_command (thd=0x7fefe8000ce8) at /home/mleich/10.4/sql/sql_parse.cc:1359
|
#23 0x0000559c5fa49bf8 in do_handle_one_connection (connect=0x559c62380a58) at /home/mleich/10.4/sql/sql_connect.cc:1412
|
#24 0x0000559c5fa49947 in handle_one_connection (arg=0x559c62380a58) at /home/mleich/10.4/sql/sql_connect.cc:1316
|
#25 0x00007ff08d1ca6db in start_thread (arg=0x7ff06c065700) at pthread_create.c:463
|
#26 0x00007ff08c3b088f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
|
perl rqg.pl \
|
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
|
--grammar=conf/mariadb/table_stress_innodb.yy \
|
--gendata=conf/mariadb/table_stress.zz \
|
--gendata_sql=conf/mariadb/table_stress.sql \
|
--engine=Innodb \
|
--reporters=Deadlock1,ErrorLog,Backtrace \
|
--mysqld=--connect_timeout=60 \
|
--mysqld=--net_read_timeout=30 \
|
--mysqld=--net_write_timeout=60 \
|
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
--mysqld=--loose-idle_transaction_timeout=0 \
|
--mysqld=--loose-idle_write_transaction_timeout=0 \
|
--mysqld=--interactive_timeout=28800 \
|
--mysqld=--lock_wait_timeout=86400 \
|
--mysqld=--innodb-lock-wait-timeout=50 \
|
--mysqld=--loose-table_lock_wait_timeout=50 \
|
--mysqld=--wait_timeout=28800 \
|
--mysqld=--slave_net_timeout=60 \
|
--mysqld=--loose-max-statement-time=30 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--mysqld=--log-output=none \
|
--duration=300 \
|
--seed=random \
|
--sqltrace=MarkErrors \
|
--threads=9 \
|
--mysqld=--innodb_adaptive_hash_index=ON \
|
--mysqld=--innodb_page_size=4K \
|
--mysqld=--innodb-buffer-pool-size=5M \
|
--no_mask \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<local settings> \
|
--basedir2=<local settings> \
|
--script_debug=_nix_ \
|
--rr=Server
|
|
How to get RQG
|
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich
|
|
AFAIR I have seen that assert on some 10.5 > 7 weeks ago.
|
|
Bug
Major
The assertion fails in a debug check that hopes to not find any locks for a particular table, in lock_table_locks_lookup(). The assertion fails on a record lock that has been logged for another table. It is for a secondary index, with lock->index->online_status == ONLINE_INDEX_ABORTED_DROPPED. We did not expect to find a record lock for such an index.
The index creation was initiated around rr replay event 221465 by
(Marvão_uidx3 interpreted in latin1 yields Marvão_uidx3 in UTF-8).
The index creation was completed at event 221792, but the transaction was not committed yet.
At event 221828, an explicit record lock for this index is created by INSERT INTO t4. As far as I understand, the statement should have a permission to execute, and it must update the freshly created but not-yet-committed secondary indexes. Any duplicate key error on those indexes must be returned to the concurrent ALTER TABLE, not to the current transaction. Here is the stack trace for the record lock creation:
10.4 ea912d1605b463a16a0c186bf10e61c4af519439
#0 lock_rec_create (c_lock=0x0, thr=0x0, type_mode=2, block=0x7fefdf72d690,heap_no=3, index=0x7feff34b0620, trx=0x7ff0888cb268,caller_owns_trx_mutex=false)at /home/mleich/10.4/storage/innobase/include/lock0lock.ic:125#1 0x0000559c5ff16188 in lock_rec_lock (impl=false, mode=2,block=0x7fefdf72d690, heap_no=3, index=0x7feff34b0620, thr=0x7feffc136580)at /home/mleich/10.4/storage/innobase/lock/lock0lock.cc:2001#2 0x0000559c5ff24086 in lock_sec_rec_read_check_and_lock (flags=0,block=0x7fefdf72d690, rec=0x7fefdf8da0a7 '3' <repeats 18 times>,index=0x7feff34b0620, offsets=0x7ff07408e040, mode=LOCK_S, gap_mode=0,thr=0x7feffc136580)at /home/mleich/10.4/storage/innobase/lock/lock0lock.cc:5763#3 0x0000559c5ffe5d51 in row_ins_set_shared_rec_lock (type=0,block=0x7fefdf72d690, rec=0x7fefdf8da0a7 '3' <repeats 18 times>,index=0x7feff34b0620, offsets=0x7ff07408e040, thr=0x7feffc136580)at /home/mleich/10.4/storage/innobase/row/row0ins.cc:1474#4 0x0000559c5ffe769e in row_ins_scan_sec_index_for_duplicate (flags=0,index=0x7feff34b0620, entry=0x7feffc0cb4c0, thr=0x7feffc136580,s_latch=true, mtr=0x7ff07408e6e0, offsets_heap=0x7feffc046af0)at /home/mleich/10.4/storage/innobase/row/row0ins.cc:2156Subsequently, at event counter 225540, the ALTER TABLE is rolled back, presumably due to MDL upgrade timeout. At event 225770, the completed uncommitted index will be flagged as garbage:
10.4 ea912d1605b463a16a0c186bf10e61c4af519439
#0 dict_index_set_online_status (index=0x7feff34b0620,status=ONLINE_INDEX_ABORTED)at /home/mleich/10.4/storage/innobase/include/dict0dict.ic:1020#1 0x0000559c60003032 in row_merge_drop_indexes (trx=0x7ff0888d4cd0,table=0x7fefdbc7f440, locked=0)at /home/mleich/10.4/storage/innobase/row/row0merge.cc:3921#2 0x0000559c5febaa96 in innobase_rollback_sec_index (user_table=0x7fefdbc7f440, table=0x7fefeb6f8428, locked=0,trx=0x7ff0888d4cd0)at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:8669#3 0x0000559c5fed11b0 in rollback_inplace_alter_table (ha_alter_info=0x7ff05c0f2da0, table=0x7fefeb6f8428,prebuilt=0x7fefeb6e59f0)at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:8763#4 0x0000559c5febf567 in ha_innobase::commit_inplace_alter_table (this=0x7fefeb6de4a0, altered_table=0x7ff05c0f2e40,ha_alter_info=0x7ff05c0f2da0, commit=false)at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:10798and at event count 225832, to the final state:
10.4 ea912d1605b463a16a0c186bf10e61c4af519439
#0 dict_index_set_online_status (index=0x7feff34b0620,status=ONLINE_INDEX_ABORTED_DROPPED)at /home/mleich/10.4/storage/innobase/include/dict0dict.ic:1020#1 0x0000559c60003218 in row_merge_drop_indexes (trx=0x7ff0888d4cd0,table=0x7fefdbc7f440, locked=0)at /home/mleich/10.4/storage/innobase/row/row0merge.cc:3946#2 0x0000559c5febaa96 in innobase_rollback_sec_index (user_table=0x7fefdbc7f440, table=0x7fefeb6f8428, locked=0,trx=0x7ff0888d4cd0)at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:8669#3 0x0000559c5fed11b0 in rollback_inplace_alter_table (ha_alter_info=0x7ff05c0f2da0, table=0x7fefeb6f8428,prebuilt=0x7fefeb6e59f0)at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:8763#4 0x0000559c5febf567 in ha_innobase::commit_inplace_alter_table (this=0x7fefeb6de4a0, altered_table=0x7ff05c0f2e40,ha_alter_info=0x7ff05c0f2da0, commit=false)After this, the assertion will fail.
I believe that the execution is correct and the debug assertion is too strict. We should merely forbid lock->index->online_status == ONLINE_INDEX_CREATION for secondary indexes.