[MDEV-24834] Assertion `mtr->memo_contains_flagged( &index->lock, MTR_MEMO_S_LOCK)' failed in btr_cur_search_to_nth_level_func Created: 2021-02-10  Updated: 2021-02-10  Resolved: 2021-02-10

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6.0
Fix Version/s: 10.6.0

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: rr-profile-analyzed

Attachments: File TBR-870.yy    
Issue Links:
Problem/Incident
is caused by MDEV-24142 rw_lock_t has unnecessarily complex w... Closed

 Description    

mysqld: /Server/10.6H/storage/innobase/btr/btr0cur.cc:1500: dberr_t btr_cur_search_to_nth_level_func(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, srw_lock*, mtr_t*, ib_uint64_t): Assertion `mtr->memo_contains_flagged( &index->lock, MTR_MEMO_S_LOCK)' failed.
 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00007f4e9100e859 in __GI_abort () at abort.c:79
 
#2  0x00007f4e9100e729 in __assert_fail_base (fmt=0x7f4e911a4588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55a86528c8a8 "mtr->memo_contains_flagged( &index->lock, MTR_MEMO_S_LOCK)", file=0x55a86528b890 "/Server/10.6H/storage/innobase/btr/btr0cur.cc", 
    line=1500, function=<optimized out>) at assert.c:92
 
#3  0x00007f4e9101ff36 in __GI___assert_fail (assertion=0x55a86528c8a8 "mtr->memo_contains_flagged( &index->lock, MTR_MEMO_S_LOCK)", file=0x55a86528b890 "/Server/10.6H/storage/innobase/btr/btr0cur.cc", line=1500, 
    function=0x55a86528c3c0 "dberr_t btr_cur_search_to_nth_level_func(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, srw_lock*, mtr_t*, ib_uint64_t)") at assert.c:101
 
#4  0x000055a864ad77e6 in btr_cur_search_to_nth_level_func (index=0x7f4e546a0858, level=0, tuple=0x7f4e5034d298, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7f4e605aaab0, ahi_latch=0x0, mtr=0x7f4e605ab100, autoinc=0) at /Server/10.6H/storage/innobase/btr/btr0cur.cc:1500
 
#5  0x000055a8649ae0b0 in btr_pcur_open_low (index=0x7f4e546a0858, level=0, tuple=0x7f4e5034d298, mode=PAGE_CUR_GE, latch_mode=16385, cursor=0x7f4e605aaab0, autoinc=0, mtr=0x7f4e605ab100) at /Server/10.6H/storage/innobase/include/btr0pcur.ic:439
 
#6  0x000055a8649b41db in row_ins_scan_sec_index_for_duplicate (flags=0, index=0x7f4e546a0858, entry=0x7f4e5034d298, thr=0x7f4e5034e858, s_latch=true, mtr=0x7f4e605ab100, offsets_heap=0x7f4e50332f88) at /Server/10.6H/storage/innobase/row/row0ins.cc:2106
 
#7  0x000055a8649b75d4 in row_ins_sec_index_entry_low (flags=0, mode=33, index=0x7f4e546a0858, offsets_heap=0x7f4e50332f88, heap=0x7f4e50334ea8, entry=0x7f4e5034d298, trx_id=0, thr=0x7f4e5034e858) at /Server/10.6H/storage/innobase/row/row0ins.cc:3062
 
#8  0x000055a8649b829a in row_ins_sec_index_entry (index=0x7f4e546a0858, entry=0x7f4e5034d298, thr=0x7f4e5034e858, check_foreign=true) at /Server/10.6H/storage/innobase/row/row0ins.cc:3349
 
#9  0x000055a864a39d5b in row_upd_sec_index_entry (node=0x7f4e54727db0, thr=0x7f4e5034e858) at /Server/10.6H/storage/innobase/row/row0upd.cc:2211
 
#10 0x000055a864a39fdf in row_upd_sec_step (node=0x7f4e54727db0, thr=0x7f4e5034e858) at /Server/10.6H/storage/innobase/row/row0upd.cc:2238
 
#11 0x000055a864a3d02d in row_upd (node=0x7f4e54727db0, thr=0x7f4e5034e858) at /Server/10.6H/storage/innobase/row/row0upd.cc:3021
 
#12 0x000055a864a3d46c in row_upd_step (thr=0x7f4e5034e858) at /Server/10.6H/storage/innobase/row/row0upd.cc:3136
 
#13 0x000055a8649df6e1 in row_update_for_mysql (prebuilt=0x7f4e54726ee8) at /Server/10.6H/storage/innobase/row/row0mysql.cc:1805
 
#14 0x000055a8648339cf in ha_innobase::update_row (this=0x7f4e546c0d20, old_row=0x7f4e546cb688 "\264\377R\001", new_row=0x7f4e546cb450 "\264\377R\001") at /Server/10.6H/storage/innobase/handler/ha_innodb.cc:8153
 
#15 0x000055a8643c7149 in handler::ha_update_row (this=0x7f4e546c0d20, old_data=0x7f4e546cb688 "\264\377R\001", new_data=0x7f4e546cb450 "\264\377R\001") at /Server/10.6H/sql/handler.cc:7204
 
#16 0x000055a864172e32 in mysql_update (thd=0x7f4e500097e8, table_list=0x7f4e5001a858, fields=..., values=..., conds=0x0, order_num=1, order=0x7f4e5001b298, limit=2, ignore=false, found_return=0x7f4e605acfd0, updated_return=0x7f4e605ad0a0)
 
    at /Server/10.6H/sql/sql_update.cc:1077
 
#17 0x000055a864049975 in mysql_execute_command (thd=0x7f4e500097e8) at /Server/10.6H/sql/sql_parse.cc:4296
 
#18 0x000055a864055e38 in mysql_parse (thd=0x7f4e500097e8, rawbuf=0x7f4e5001a700 "UPDATE t1 SET col1 = NULL ORDER BY col1 DESC LIMIT 2  /* E_R Thread2 QNO 739 CON_ID 16 */", length=89, parser_state=0x7f4e605ad510) at /Server/10.6H/sql/sql_parse.cc:7906
 
#19 0x000055a86404237b in dispatch_command (command=COM_QUERY, thd=0x7f4e500097e8, packet=0x7f4e500112b9 "UPDATE t1 SET col1 = NULL ORDER BY col1 DESC LIMIT 2  /* E_R Thread2 QNO 739 CON_ID 16 */ ", packet_length=90) at /Server/10.6H/sql/sql_parse.cc:1833
 
#20 0x000055a864040d92 in do_command (thd=0x7f4e500097e8) at /Server/10.6H/sql/sql_parse.cc:1365
 
#21 0x000055a8641ee55c in do_handle_one_connection (connect=0x55a866955f68, put_in_cache=true) at /Server/10.6H/sql/sql_connect.cc:1410
 
#22 0x000055a8641ee2c4 in handle_one_connection (arg=0x55a866955968) at /Server/10.6H/sql/sql_connect.cc:1312
 
#23 0x000055a86474bd0b in pfs_spawn_thread (arg=0x55a8669559d8) at /Server/10.6H/storage/perfschema/pfs.cc:2201
 
#24 0x00007f4e91537609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#25 0x00007f4e9110b293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr)
 
pluto:/home/mleich/RQG_O/ANSEHEN10.6/TBR-870/dev/shm/vardir/1612869997/23/1/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0
 
 
 
origin/10.6, 10.6 786bc312b85e58857cb26a24ab6e997ba0fdfc32 2021-02-07T13:21:18+02:00
 
 
 
RQG
 
===
 
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
 
 
rqg.pl \ 
--duration=300 \
 
--queries=10000000 \
 
--no_mask \
 
--seed=random \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--engine=InnoDB \
 
--rpl_mode=none \
 
--gendata=conf/mariadb/table_stress.zz \
 
--mysqld=--innodb_adaptive_hash_index=on \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--log-bin \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--innodb-buffer-pool-size=256M \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--loose-max-statement-time=30 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--innodb_page_size=4K \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--log-output=none \
 
--mysqld=--lock-wait-timeout=86400 \
 
--reporters=Backtrace,Deadlock1,ErrorLog \
 
--validators=None \
 
--threads=33 \
 
--grammar=TBR-870.yy \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> \
 
--script_debug=_nix_ \
 
--rr=Extended



 Comments   
Comment by Marko Mäkelä [ 2021-02-10 ]

This looks like a bogus debug assertion. The failing assertion is calling the following:

#0  mtr_t::memo_contains_flagged (this=0x7f4e605ab100, ptr=0x7f4e546a09c8, 
    flags=32) at /Server/10.6H/storage/innobase/mtr/mtr0mtr.cc:1195
 
(rr) p *(mtr_memo_slot_t*)m_memo.m_first_block.m_data@m_memo.m_size/sizeof(mtr_memo_slot_t)
 
$1 = {{object = 0x7f4e546a09c8, type = MTR_MEMO_SX_LOCK}}

So, we see that the requested object has been latched, in a stronger mode that is being demanded. It was done in row_ins_sec_index_entry_low():

	const bool	check = !index->is_committed();
 
	if (check) {
 
		DEBUG_SYNC_C("row_ins_sec_index_enter");
 
		if (mode == BTR_MODIFY_LEAF) {
 
			search_mode |= BTR_ALREADY_S_LATCHED;
 
			mtr_s_lock_index(index, &mtr);
 
		} else {
 
			mtr_sx_lock_index(index, &mtr);
 
		}

The assertion was changed in MDEV-24142 but the semantics was supposed to be retained. The latch acquisition code was last changed even earlier in MDEV-12353, but the semantics was retained. The latch acquisition was changed when the InnoDB changes from MySQL 5.7.9 were applied to MariaDB 10.2.2. That commit did include a valid assertion, which did not refer to mtr_t at all:

                         if (s_latch_by_caller) {
 
                                 ut_ad(rw_lock_own(dict_index_get_lock(index),
 
                                               RW_LOCK_S));

It looks like the problem was indeed introduced in the MDEV-24142 commit, when rw_lock_own() was replaced with mtr_t::memo_contains_added(). I think that we must simply amend the call with the flag MTR_MEMO_SX_LOCK.

Generated at Thu Feb 08 09:33:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.