[MDEV-24590] Assertion `!other_lock' failed in lock_rec_add_to_queue Created: 2021-01-14  Updated: 2023-01-26

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5.9
Fix Version/s: 10.5

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 0
Labels: need_rr


 Description   

mysqld: /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:1775: void lock_rec_add_to_queue(unsigned int, const buf_block_t*, ulint, dict_index_t*, trx_t*, bool): Assertion `!other_lock' failed.
...
Query (0x62b000196238): INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) )
Connection ID (thread ID): 32
Status: NOT_KILLED
 
sdp:/home/mleich/RQG_O/storage/1610563808/tmp1/dev/shm/vardir/1610563808/173/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000028411bded859 in __GI_abort () at abort.c:79
#2  0x000028411bded729 in __assert_fail_base (fmt=0x28411bf83588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55a435d77cc0 "!other_lock", file=0x55a435d758e0 "/Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc", line=1775, 
    function=<optimized out>) at assert.c:92
#3  0x000028411bdfef36 in __GI___assert_fail (assertion=0x55a435d77cc0 "!other_lock", file=0x55a435d758e0 "/Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc", line=1775, 
    function=0x55a435d77b40 "void lock_rec_add_to_queue(unsigned int, const buf_block_t*, ulint, dict_index_t*, trx_t*, bool)") at assert.c:101
#4  0x000055a4344e2a7d in lock_rec_add_to_queue (type_mode=35, block=0x4a3e2d3c1520, heap_no=2, index=0x6170003277a0, trx=0x74905a4644c0, caller_owns_trx_mutex=false) at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:1775
#5  0x000055a4344e7ad4 in lock_move_rec_list_end (new_block=0x4a3e2d3c1520, block=0x4a3e2d3c66b0, rec=0x4a3e2d7ce065 "infimum") at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:2710
#6  0x000055a4345c6a0e in page_copy_rec_list_end (new_block=0x4a3e2d3c1520, block=0x4a3e2d3c66b0, rec=0x4a3e2d7ce065 "infimum", index=0x6170003277a0, mtr=0x38c21e5e4dc0) at /Server/bb-10.5-MDEV-24569/storage/innobase/page/page0page.cc:658
#7  0x000055a4348cdc15 in btr_root_raise_and_insert (flags=0, cursor=0x38c21e5e49a0, offsets=0x38c21e5e4920, heap=0x38c21e5e4900, tuple=0x61700047ac20, n_ext=1, mtr=0x38c21e5e4dc0)
    at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:1904
#8  0x000055a43491ea43 in btr_cur_pessimistic_insert (flags=0, cursor=0x38c21e5e49a0, offsets=0x38c21e5e4920, heap=0x38c21e5e4900, entry=0x61700047ac20, rec=0x38c21e5e4940, big_rec=0x38c21e5e48e0, n_ext=1, thr=0x621000447ca0, mtr=0x38c21e5e4dc0)
    at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0cur.cc:3746
#9  0x000055a434694e0e in row_ins_clust_index_entry_low (flags=0, mode=33, index=0x6170003277a0, n_uniq=0, entry=0x61700047ac20, n_ext=0, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:2755
#10 0x000055a434697980 in row_ins_clust_index_entry (index=0x6170003277a0, entry=0x61700047ac20, thr=0x621000447ca0, n_ext=0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3225
#11 0x000055a434698154 in row_ins_index_entry (index=0x6170003277a0, entry=0x61700047ac20, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3333
#12 0x000055a4346992c5 in row_ins_index_entry_step (node=0x6210004477c0, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3502
#13 0x000055a434699d9e in row_ins (node=0x6210004477c0, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3661
#14 0x000055a43469afb9 in row_ins_step (thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3807
#15 0x000055a4346e4abd in row_insert_for_mysql (mysql_rec=0x61a00086eeb8 "\320\001", prebuilt=0x6210004471a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0mysql.cc:1421
#16 0x000055a434343582 in ha_innobase::write_row (this=0x61d000a122b8, record=0x61a00086eeb8 "\320\001") at /Server/bb-10.5-MDEV-24569/storage/innobase/handler/ha_innodb.cc:7545
#17 0x000055a433840d51 in handler::ha_write_row (this=0x61d000a122b8, buf=0x61a00086eeb8 "\320\001") at /Server/bb-10.5-MDEV-24569/sql/handler.cc:7151
#18 0x000055a432f4c43e in write_record (thd=0x62b00018f218, table=0x61900064d798, info=0x38c21e5e6820, sink=0x0) at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:2106
#19 0x000055a432f43efb in mysql_insert (thd=0x62b00018f218, table_list=0x62b0001964b8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
    at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:1099
#20 0x000055a43300c790 in mysql_execute_command (thd=0x62b00018f218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:4596
#21 0x000055a433024c98 in mysql_parse (thd=0x62b00018f218, 
    rawbuf=0x62b000196238 "INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread17 QNO 188 C"..., length=211, 
    parser_state=0x38c21e5e77c0, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
#22 0x000055a432ffaf91 in dispatch_command (command=COM_QUERY, thd=0x62b00018f218, 
    packet=0x6290007df219 " INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread17 QNO 188 "..., 
    packet_length=213, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1889
#23 0x000055a432ff78ba in do_command (thd=0x62b00018f218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1370
#24 0x000055a433439b71 in do_handle_one_connection (connect=0x60800000d6b8, put_in_cache=true) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1410
#25 0x000055a4334394da in handle_one_connection (arg=0x60800000d6b8) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1312
#26 0x000055a4341442eb in pfs_spawn_thread (arg=0x61500000e918) at /Server/bb-10.5-MDEV-24569/storage/perfschema/pfs.cc:2201
#27 0x00007f67f5fef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#28 0x000028411beea293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr)
 
origin/bb-10.5-MDEV-24569 2181fa74fdda0bba8a2cc92b555e39d0b9162877 2021-01-13T21:54:30+05:30
 
RQG
====
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
perl rqg.pl \
--grammar=conf/mariadb/table_stress_innodb.yy \
--gendata=conf/mariadb/table_stress.zz \
--gendata_sql=conf/mariadb/table_stress.sql \
--reporters=CrashRecovery1 \
--mysqld=--innodb_use_native_aio=1 \
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--connect_timeout=60 \
--mysqld=--interactive_timeout=28800 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--net_read_timeout=30 \
--mysqld=--net_write_timeout=60 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--wait_timeout=28800 \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--innodb-lock-wait-timeout=50 \
--no-mask \
--queries=10000000 \
--seed=random \
--reporters=Backtrace \
--reporters=ErrorLog \
--reporters=Deadlock1 \
--validators=None \
--mysqld=--log_output=none \
--mysqld=--log-bin \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--engine=InnoDB \
--restart_timeout=120 \
--mysqld=--plugin-load-add=file_key_management.so \
--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
--duration=300 \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
--mysqld=--loose-innodb-sync-debug \
--mysqld=--innodb_stats_persistent=on \
--mysqld=--loose-max-statement-time=30 \
--threads=33 \
--mysqld=--innodb_page_size=8K \
--mysqld=--innodb-buffer-pool-size=8M \
--duration=300 \
--no_mask \
--workdir=<local settings> \
--vardir=<local settings> \
--mtr-build-thread=<local settings> \
--basedir1=<local settings> \
--script_debug=_nix_ \
--rr=Extended \
--rr_options=--chaos
 
The reporter "CrashRecovery1" gets loaded but the assert happens before
that reporter starts to really work.



 Comments   
Comment by Matthias Leich [ 2021-01-14 ]

There is some brute force attempt to generate a simplified test already running.
But up till now no replay at all.

Comment by Marko Mäkelä [ 2021-04-12 ]

mleich, sorry, the trace is no longer valid:

rr replay /home/mleich/RQG_O/storage/1610563808/tmp1/dev/shm/vardir/1610563808/173/1/rr/latest-trace
[FATAL /home/roc/rr/rr/src/TraceStream.cc:1115:read_mapped_region() errno: ENOENT] Failed to stat /home/mleich/Server_bin/bb-10.5-MDEV-24569_asan/bin/mariadbd: replay is impossible

Do you have another trace of this?

Comment by Matthias Leich [ 2021-04-12 ]

All other traces have the same problem.
I will try to generate a new trace.

Comment by Matthias Leich [ 2022-06-23 ]

Replaying this problem was quite rare in general.
It was replayed last time 2022 January till March on
origin/bb-10.9-MDEV-27812 ca7065763c54a3e09ab2fc508c8200a9ec81b6e1 2022-02-25T17:32:19+02:00
pluto:/data/results/1645803786/004395.tar.xz
origin/bb-10.8-MDEV-14425 14eaeb68e60626a9b1e4f4b611f0bc23a79f7202 2022-01-20T13:35:18+02:00
origin/bb-10.6-release 6dd07fbd042132729e5dea0a6a9b35f07a33e9e5 2022-02-03T16:51:08+02:00
 
I guess that it was fixed by a nice side effect since than.
Please show up in case you are interested in the rr traces.

Comment by Marko Mäkelä [ 2022-06-23 ]

Possible fix candidates could be MDEV-20605 (2022-02-21) or MDEV-28422 (2022-04-27). Let us keep this open in case this occurs again.

Comment by Matthias Leich [ 2023-01-26 ]

 
origin/bb-10.6-MDEV-27701-wait_lock-race, bb-10.6-MDEV-27701-wait_lock-race 51377f8a893b8e120760dd883bb8f8f06b3d39e9 2023-01-26T17:17:05+03:00
10.6.12
 
# 2023-01-26T09:07:49 [3157362] | mysqld: /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/lock/lock0lock.cc:1400: bool lock_rec_add_to_queue(unsigned int, hash_cell_t&, page_id_t, const ib_page_t*, ulint, const dict_index_t*, trx_t*, bool) [with bool try_wait_lock = false; ib_page_t = unsigned char; ulint = long unsigned int]: Assertion `!other_lock' failed.
# 2023-01-26T09:07:49 [3157362] | Query (0x62b000173238): ROLLBACK  /* E_R Thread10 QNO 1806 CON_ID 499 */
# 2023-01-26T09:07:49 [3157362] | Status: NOT_KILLED
 
# 2023-01-26T09:07:49 [3157362] #5  <signal handler called>
# 2023-01-26T09:07:49 [3157362] #6  __pthread_kill_implementation (no_tid=0, signo=6, threadid=139906503374400) at ./nptl/pthread_kill.c:44
# 2023-01-26T09:07:49 [3157362] #7  __pthread_kill_internal (signo=6, threadid=139906503374400) at ./nptl/pthread_kill.c:78
# 2023-01-26T09:07:49 [3157362] #8  __GI___pthread_kill (threadid=139906503374400, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
# 2023-01-26T09:07:49 [3157362] #9  0x00007f3eac207476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
# 2023-01-26T09:07:49 [3157362] #10 0x00007f3eac1ed7f3 in __GI_abort () at ./stdlib/abort.c:79
# 2023-01-26T09:07:49 [3157362] #11 0x00007f3eac1ed71b in __assert_fail_base (fmt=0x7f3eac3a2150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x56140d465fc0 "!other_lock", file=0x56140d45e8c0 "/data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/lock/lock0lock.cc", line=1400, function=<optimized out>) at ./assert/assert.c:92
# 2023-01-26T09:07:49 [3157362] #12 0x00007f3eac1fee96 in __GI___assert_fail (assertion=0x56140d465fc0 "!other_lock", file=0x56140d45e8c0 "/data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/lock/lock0lock.cc", line=1400, function=0x56140d468e00 "bool lock_rec_add_to_queue(unsigned int, hash_cell_t&, page_id_t, const ib_page_t*, ulint, const dict_index_t*, trx_t*, bool) [with bool try_wait_lock = false; ib_page_t = unsigned char; ulint = long unsigned int]") at ./assert/assert.c:101
# 2023-01-26T09:07:49 [3157362] #13 0x000056140bec46d7 in lock_rec_add_to_queue<>(unsigned int, hash_cell_t &, page_id_t, const ib_page_t *, ulint, const dict_index_t *, trx_t *, bool) (type_mode=1026, cell=..., id=..., page=0x7f3e4b3f0000 "", heap_no=0, index=0x61600355ba08, trx=0x7f3ea0843040, caller_owns_trx_mutex=true) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/lock/lock0lock.cc:1400
# 2023-01-26T09:07:49 [3157362] #14 0x000056140bec6684 in lock_rec_move<false> (receiver_cell=..., receiver=..., receiver_id=..., donator_cell=..., donator_id=..., receiver_heap_no=0, donator_heap_no=4) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/lock/lock0lock.cc:2256
# 2023-01-26T09:07:49 [3157362] #15 0x000056140beaacbb in lock_rec_store_on_page_infimum (block=0x7f3e4a790010, rec=0x7f3e4b3f00c7 "\200") at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/lock/lock0lock.cc:3282
# 2023-01-26T09:07:49 [3157362] #16 0x000056140c2b108e in btr_cur_pessimistic_update (flags=7, cursor=0x61a0007b1978, offsets=0x7f3e856f40d0, offsets_heap=0x7f3e856f40b0, entry_heap=0x619000a88980, big_rec=0x7f3e856f3f70, update=0x6180001bad08, cmpl_info=0, thr=0x6160058dd1c0, trx_id=23140, mtr=0x7f3e856f4190) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/btr/btr0cur.cc:4594
# 2023-01-26T09:07:49 [3157362] #17 0x000056140c519c76 in row_undo_mod_clust_low (node=0x61a0007b1908, offsets=0x7f3e856f40d0, offsets_heap=0x7f3e856f40b0, heap=0x619000a88980, sys=0x7f3e856f4490 "\300Do\205>\177", thr=0x6160058dd1c0, mtr=0x7f3e856f4190, mode=BTR_MODIFY_TREE) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/row/row0umod.cc:122
# 2023-01-26T09:07:49 [3157362] #18 0x000056140c51b524 in row_undo_mod_clust (node=0x61a0007b1908, thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/row/row0umod.cc:294
# 2023-01-26T09:07:49 [3157362] #19 0x000056140c521e77 in row_undo_mod (node=0x61a0007b1908, thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/row/row0umod.cc:1243
# 2023-01-26T09:07:49 [3157362] #20 0x000056140c155e0c in row_undo (node=0x61a0007b1908, thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/row/row0undo.cc:405
# 2023-01-26T09:07:49 [3157362] #21 0x000056140c156307 in row_undo_step (thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/row/row0undo.cc:452
# 2023-01-26T09:07:49 [3157362] #22 0x000056140bff617d in que_thr_step (thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/que/que0que.cc:595
# 2023-01-26T09:07:49 [3157362] #23 0x000056140bff6570 in que_run_threads_low (thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/que/que0que.cc:653
# 2023-01-26T09:07:49 [3157362] #24 0x000056140bff672d in que_run_threads (thr=0x6160058dd1c0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/que/que0que.cc:673
# 2023-01-26T09:07:49 [3157362] #25 0x000056140c1f46c4 in trx_t::rollback_low (this=0x7f3ea0839640, savept=0x0) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/trx/trx0roll.cc:125
# 2023-01-26T09:07:49 [3157362] #26 0x000056140c1ee80a in trx_rollback_for_mysql_low (trx=0x7f3ea0839640) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/trx/trx0roll.cc:196
# 2023-01-26T09:07:49 [3157362] #27 0x000056140c1eeefc in trx_rollback_for_mysql (trx=0x7f3ea0839640) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/trx/trx0roll.cc:231
# 2023-01-26T09:07:49 [3157362] #28 0x000056140bd0c495 in innobase_rollback (hton=0x615000001498, thd=0x62b00016c218, rollback_trx=true) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/storage/innobase/handler/ha_innodb.cc:4697
# 2023-01-26T09:07:49 [3157362] #29 0x000056140b437055 in ha_rollback_trans (thd=0x62b00016c218, all=true) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/sql/handler.cc:2199
# 2023-01-26T09:07:49 [3157362] #30 0x000056140b08273b in trans_rollback (thd=0x62b00016c218) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/sql/transaction.cc:372
# 2023-01-26T09:07:49 [3157362] #31 0x000056140ac60720 in mysql_execute_command (thd=0x62b00016c218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/sql/sql_parse.cc:5660
# 2023-01-26T09:07:49 [3157362] #32 0x000056140ac6ea7e in mysql_parse (thd=0x62b00016c218, rawbuf=0x62b000173238 "ROLLBACK  /* E_R Thread10 QNO 1806 CON_ID 499 */", length=48, parser_state=0x7f3e856f5890) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/sql/sql_parse.cc:8019
# 2023-01-26T09:07:49 [3157362] #33 0x000056140ac46f4e in dispatch_command (command=COM_QUERY, thd=0x62b00016c218, packet=0x629000ce9219 " ROLLBACK  /* E_R Thread10 QNO 1806 CON_ID 499 */ ", packet_length=50, blocking=true) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/sql/sql_parse.cc:1896
# 2023-01-26T09:07:49 [3157362] #34 0x000056140ac4445a in do_command (thd=0x62b00016c218, blocking=true) at /data/Server/bb-10.6-MDEV-27701-wait_lock-race/sql/sql_parse.cc:1409

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