[MDEV-15658] Assertion `!expl_lock || expl_lock->trx == arg->impl_trx' failed in lock_rec_other_trx_holds_expl_callback Created: 2018-03-25  Updated: 2019-03-27  Resolved: 2019-03-27

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.14, 10.4.4, 10.3, 10.4
Fix Version/s: 10.3.14, 10.4.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: affects-tests, debug

Attachments: File MDEV-15658.tgz     File mysql.err     File mysql.err     File mysql.log     File mysql.log     HTML File threads    
Issue Links:
Problem/Incident
is caused by MDEV-14638 Replace trx_sys_t::rw_trx_set with LF... Closed

 Description   

10.3 ad647cc84ebf331d59b24e81bffe89be2f5b1ed7

 
mysqld: /home/travis/src/storage/innobase/lock/lock0lock.cc:6182: my_bool lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*): Assertion `!expl_lock || expl_lock->trx == arg->impl_trx' failed.
 
180325  8:25:01 [ERROR] mysqld got signal 6 ;
 
 
 
Query (0x7fca1025dda8): INSERT INTO transforms.trigger27372 SELECT `col_enum_utf8_key` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* QNO 466 CON_ID 16 */
 
Connection ID (thread ID): 16
 
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on


#6  0x00007fca6f14dbf6 in __assert_fail_base (fmt=0x7fca6f2a2058 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x562e396d4150 "!expl_lock || expl_lock->trx == arg->impl_trx", file=file@entry=0x562e396d1a50 "/home/travis/src/storage/innobase/lock/lock0lock.cc", line=line@entry=6182, function=function@entry=0x562e396d91a0 <lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)::__PRETTY_FUNCTION__> "my_bool lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)") at assert.c:92
 
#7  0x00007fca6f14dca2 in __GI___assert_fail (assertion=0x562e396d4150 "!expl_lock || expl_lock->trx == arg->impl_trx", file=0x562e396d1a50 "/home/travis/src/storage/innobase/lock/lock0lock.cc", line=6182, function=0x562e396d91a0 <lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)::__PRETTY_FUNCTION__> "my_bool lock_rec_other_trx_holds_expl_callback(rw_trx_hash_element_t*, lock_rec_other_trx_holds_expl_arg*)") at assert.c:101
 
#8  0x0000562e38f24ea3 in lock_rec_other_trx_holds_expl_callback (element=0x7fca240e96a0, arg=0x7fca6c0a5e30) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6182
 
#9  0x0000562e38f2a671 in rw_trx_hash_t::debug_iterator (element=0x7fca240e96a0, arg=0x7fca6c0a5df0) at /home/travis/src/storage/innobase/include/trx0sys.h:541
 
#10 0x0000562e39445b87 in l_find (head=0x7fca1c03d000, cs=0x0, hashnr=0, key=0x7fca6c0a5df0 "\321M\362\070.V", keylen=0, cursor=0x7fca6c0a5d90, pins=0x562e3c598600, callback=0x562e38f2a5ea <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>) at /home/travis/src/mysys/lf_hash.c:126
 
#11 0x0000562e3944682e in lf_hash_iterate (hash=0x562e39f00a40 <trx_sys+2496>, pins=0x562e3c598600, action=0x562e38f2a5ea <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>, argument=0x7fca6c0a5df0) at /home/travis/src/mysys/lf_hash.c:518
 
#12 0x0000562e38f2a88b in rw_trx_hash_t::iterate (this=0x562e39f00a40 <trx_sys+2496>, caller_trx=0x7fca598dd948, action=0x562e38f2a5ea <rw_trx_hash_t::debug_iterator(rw_trx_hash_element_t*, rw_trx_hash_t::debug_iterator_arg*)>, argument=0x7fca6c0a5df0) at /home/travis/src/storage/innobase/include/trx0sys.h:744
 
#13 0x0000562e38f24f97 in lock_rec_other_trx_holds_expl (caller_trx=0x7fca598dd948, trx=0x7fca598ddde0, rec=0x7fca4c5c8283 "\020\200", block=0x7fca4ba45600) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6216
 
#14 0x0000562e38f25282 in lock_rec_convert_impl_to_expl (caller_trx=0x7fca598dd948, block=0x7fca4ba45600, rec=0x7fca4c5c8283 "\020\200", index=0x7fca100ce0a8, offsets=0x7fca6c0a6970) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6258
 
#15 0x0000562e38f25e84 in lock_sec_rec_read_check_and_lock (flags=0, block=0x7fca4ba45600, rec=0x7fca4c5c8283 "\020\200", index=0x7fca100ce0a8, offsets=0x7fca6c0a6970, mode=LOCK_S, gap_mode=0, thr=0x7fca2005a3f0) at /home/travis/src/storage/innobase/lock/lock0lock.cc:6466
 
#16 0x0000562e39026cee in sel_set_rec_lock (pcur=0x7fca20059b28, rec=0x7fca4c5c8283 "\020\200", index=0x7fca100ce0a8, offsets=0x7fca6c0a6970, mode=2, type=0, thr=0x7fca2005a3f0, mtr=0x7fca6c0a6c90) at /home/travis/src/storage/innobase/row/row0sel.cc:1263
 
#17 0x0000562e3902fa3c in row_search_mvcc (buf=0x7fca10261e52 '\245' <repeats 200 times>..., mode=PAGE_CUR_G, prebuilt=0x7fca20059958, match_mode=0, direction=1) at /home/travis/src/storage/innobase/row/row0sel.cc:4931
 
#18 0x0000562e38e9af0f in ha_innobase::general_fetch (this=0x7fca2003d9e8, buf=0x7fca10261e52 '\245' <repeats 200 times>..., direction=1, match_mode=0) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9854
 
#19 0x0000562e38e9b18c in ha_innobase::index_next (this=0x7fca2003d9e8, buf=0x7fca10261e52 '\245' <repeats 200 times>...) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:9921
 
#20 0x0000562e38c891b6 in handler::ha_index_next (this=0x7fca2003d9e8, buf=0x7fca10261e52 '\245' <repeats 200 times>...) at /home/travis/src/sql/handler.cc:2862
 
#21 0x0000562e393fe971 in ha_partition::handle_ordered_next (this=0x7fca2003be58, buf=0x7fca200402d8 '\245' <repeats 200 times>..., is_next_same=false) at /home/travis/src/sql/ha_partition.cc:7898
 
#22 0x0000562e393f80dc in ha_partition::index_next (this=0x7fca2003be58, buf=0x7fca200402d8 '\245' <repeats 200 times>...) at /home/travis/src/sql/ha_partition.cc:5796
 
#23 0x0000562e38c891b6 in handler::ha_index_next (this=0x7fca2003be58, buf=0x7fca200402d8 '\245' <repeats 200 times>...) at /home/travis/src/sql/handler.cc:2862
 
#24 0x0000562e38a0ae99 in join_read_next (info=0x7fca1025ef90) at /home/travis/src/sql/sql_select.cc:20232
 
#25 0x0000562e38901289 in READ_RECORD::read_record (this=0x7fca1025ef90) at /home/travis/src/sql/records.h:73
 
#26 0x0000562e38a0888c in sub_select (join=0x7fca1025df58, join_tab=0x7fca1025eec8, end_of_records=false) at /home/travis/src/sql/sql_select.cc:19251
 
#27 0x0000562e38a07d4b in do_select (join=0x7fca1025df58, procedure=0x0) at /home/travis/src/sql/sql_select.cc:18772
 
#28 0x0000562e389e0f10 in JOIN::exec_inner (this=0x7fca1025df58) at /home/travis/src/sql/sql_select.cc:3987
 
#29 0x0000562e389e03b0 in JOIN::exec (this=0x7fca1025df58) at /home/travis/src/sql/sql_select.cc:3781
 
#30 0x0000562e389e1624 in mysql_select (thd=0x7fca10015900, tables=0x7fca104e6dd0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=553245477632, result=0x7fca1025deb0, unit=0x7fca104e5730, select_lex=0x7fca104e5ea8) at /home/travis/src/sql/sql_select.cc:4186
 
#31 0x0000562e389d38f7 in handle_select (thd=0x7fca10015900, lex=0x7fca104e5668, result=0x7fca1025deb0, setup_tables_done_option=1073741824) at /home/travis/src/sql/sql_select.cc:382
 
#32 0x0000562e389983be in mysql_execute_command (thd=0x7fca10015900) at /home/travis/src/sql/sql_parse.cc:4826
 
#33 0x0000562e388c682c in sp_instr_stmt::exec_core (this=0x7fca104e5040, thd=0x7fca10015900, nextp=0x7fca6c0a8a9c) at /home/travis/src/sql/sp_head.cc:3595
 
#34 0x0000562e388c5c44 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fca104e5090, thd=0x7fca10015900, nextp=0x7fca6c0a8a9c, open_tables=false, instr=0x7fca104e5040) at /home/travis/src/sql/sp_head.cc:3311
 
#35 0x0000562e388c63e9 in sp_instr_stmt::execute (this=0x7fca104e5040, thd=0x7fca10015900, nextp=0x7fca6c0a8a9c) at /home/travis/src/sql/sp_head.cc:3498
 
#36 0x0000562e388c01d8 in sp_head::execute (this=0x7fca104e35c8, thd=0x7fca10015900, merge_da_on_success=false) at /home/travis/src/sql/sp_head.cc:1349
 
#37 0x0000562e388c132d in sp_head::execute_trigger (this=0x7fca104e35c8, thd=0x7fca10015900, db_name=0x7fca104ea898, table_name=0x7fca104ea8a8, grant_info=0x7fca104f1098) at /home/travis/src/sql/sp_head.cc:1757
 
#38 0x0000562e38a7f42d in Table_triggers_list::process_triggers (this=0x7fca104f0ab8, thd=0x7fca10015900, event=TRG_EVENT_INSERT, time_type=TRG_ACTION_BEFORE, old_row_is_record1=true) at /home/travis/src/sql/sql_trigger.cc:2204
 
#39 0x0000562e38918662 in fill_record_n_invoke_before_triggers (thd=0x7fca10015900, table=0x7fca104eeb70, ptr=0x7fca104ef7c8, values=..., ignore_errors=false, event=TRG_EVENT_INSERT) at /home/travis/src/sql/sql_base.cc:8513
 
#40 0x0000562e3895a489 in mysql_insert (thd=0x7fca10015900, table_list=0x7fca1002c500, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/travis/src/sql/sql_insert.cc:1011
 
#41 0x0000562e38997c5a in mysql_execute_command (thd=0x7fca10015900) at /home/travis/src/sql/sql_parse.cc:4719
 
#42 0x0000562e389a2454 in mysql_parse (thd=0x7fca10015900, rawbuf=0x7fca1002c3c8 "INSERT INTO trigger17372 VALUES (1) /* QNO 528 CON_ID 16 */", length=59, parser_state=0x7fca6c0aa5e0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8009
 
#43 0x0000562e3898fb4d in dispatch_command (command=COM_QUERY, thd=0x7fca10015900, packet=0x7fca10068621 "INSERT INTO trigger17372 VALUES (1) /* QNO 528 CON_ID 16 */ ", packet_length=60, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1838
 
#44 0x0000562e3898e599 in do_command (thd=0x7fca10015900) at /home/travis/src/sql/sql_parse.cc:1383
 
#45 0x0000562e38af37c3 in do_handle_one_connection (connect=0x562e3b840050) at /home/travis/src/sql/sql_connect.cc:1402
 
#46 0x0000562e38af3550 in handle_one_connection (arg=0x562e3b840050) at /home/travis/src/sql/sql_connect.cc:1308
 
#47 0x00007fca6fd0f184 in start_thread (arg=0x7fca6c0ab700) at pthread_create.c:312
 
#48 0x00007fca6f21c03d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111



 Comments   
Comment by Matthias Leich [ 2018-08-22 ]

9 replays within ~1000 RQG runs on
origin/10.3 c43d11b96e27f25d248f4740a2274f1bfb1d5845 2018-08-21T12:27:29-07:00
10.3.10-MariaDB-debug-log

Comment by Matthias Leich [ 2019-01-21 ] 

Replay of the problem (same assert hit) on
 
   10.4 commit 4edb29380c98058a28e49c826bacee9c83473579 2019-01-18
 
with
 
   my "experimental" RQG
 
   git clone https://github.com/mleich1/rqg --branch experimental RQG_new2
 
and
 
/work/RQG_new2/rqg.pl \ 
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
 
--grammar=conf/mariadb/table_stress.yy \
 
--gendata=conf/mariadb/table_stress.zz \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--engine=Innodb \
 
--reporters=Deadlock,ErrorLog,Backtrace \
 
--mysqld=--loose_innodb_use_native_aio=0 \
 
--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=--log-output=none \
 
--duration=300 \
 
--seed=random \
 
--sqltrace=MarkErrors \
 
--threads=32 \
 
--mysqld=--innodb-flush-log-at-trx-commit=2 \
 
--mysqld=--transaction-isolation=READ-COMMITTED \
 
--grammar=table_stress.yy \
 
--threads=12 \
 
--workdir=<..> \
 
--vardir=<...> \
 
--mtr-build-thread=<...> \
 
--basedir1=<...>
 
<...> == Setting specific to the testing box and point of time of RQG run.
 
But the likelihood to replay that problem is extreme low
 
      8 CPU box, 1h ~90% CPU busy, 300 RQG runs, 1 replay only

Comment by Matthias Leich [ 2019-03-21 ] 

MDEV-15658.tgz contains my MTR based test for replaying the problem.
 
The replay testcase requires some Linux.
 
 
 
cd <source_dir>/mysql-test
 
tar xvzf <path_to_dir_with_archive>/MDEV-15658.tgz
 
       main/MDEV-15658.test 
       mysqltest_background.sh
 
cd <build_dir>/mysql-test
 
./mysql-test-run.pl --mem MDEV-15658
 
You will see
 
- a bit SQL 
- many times the output of SHOW PROCESSLIST
 
hopefully followed finally by the assert.
 
 
 
Quite fast replay on
 
10.3.14 commit 51e48b9f8981986257a1cfbdf75e4fc29a5959c1
 
10.4.4    commit 514b305dfb2839c619a623bbdae5f21cf0077672 2019-02-20
 
I had several attempts to replay the problem on
 
10.2 commit 1caec9c8982a73f3db78fabc570934b837658109 2019-03-21
 
without success.
 
 
 
Sorry for the properties of mysqltest_background.sh but up till today
 
I have not found a better way for MTR based brute force tests which
 
replay problems found with RQG.

Comment by Marko Mäkelä [ 2019-03-27 ]

This turned out to be a bug in the debug check only. Non-debug executables were not affected.

Generated at Thu Feb 08 08:23:03 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.