[MDEV-31815] Assertion `mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK)' failed in btr_attach_half_pages on INSERT (2k threads) Created: 2023-08-01  Updated: 2023-11-30

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

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 0
Labels: multi-thread, rr-elusive, sporadic

Issue Links:
Relates
relates to MDEV-29835 Partial server freeze Closed

 Description    

#!/bin/bash
 
# Start server with --max_connections=10000
 
# Set variables and ensure ramloc is a ramdisk or tmpfs (i.e. /dev/shm)
 
 
user="root"
 
socket="./socket.sock"
 
db="test"
 
client="./bin/mariadb"
 
errorlog="./log/master.err"
 
ramloc="/dev/shm"
 
threads=2000   # Number of concurrent threads
 
queries=100    # Number of t1/t2 INSERTs per thread/per test round
 
rounds=999999  # Number of max test rounds
 
 
# Setup
 
${client} -u ${user} -S ${socket} -D ${db} -e "
 
DROP TABLE IF EXISTS t1;
 
DROP TABLE IF EXISTS t2;
 
CREATE TABLE t1 (c1 INT NOT NULL AUTO_INCREMENT, c2 INT NOT NULL, PRIMARY KEY (c1), UNIQUE KEY u1 (c1,c2)) ENGINE=InnoDB AUTO_INCREMENT=1 ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4; 
CREATE TABLE t2 (c1 DATETIME NOT NULL, c2 DOUBLE NOT NULL, t1_c1 INT NOT NULL, PRIMARY KEY (t1_c1,c1)) ENGINE=InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4;
 
"
 
 
insert_rows(){
 
  SQL=
 
  for ((i=0;i<${queries};i++)); do
 
    SQL="${SQL}INSERT INTO t1 (c2) VALUES (0); INSERT INTO t2 VALUES (CURRENT_TIMESTAMP, 0, (SELECT LAST_INSERT_ID()));"
 
  done
 
  ${client} -u ${user} -S ${socket} -D ${db} -e "${SQL}"
 
  rm -f ${ramloc}/${prefix}_md_proc_${1}  # Thread done
 
}
 
 
abort(){ jobs -p | xargs -P100 kill >/dev/null 2>&1; rm -Rf ${ramloc}/${prefix}_md_proc_*; exit 1; }
 
trap abort SIGINT
 
 
count=0
 
prefix="$(echo "${RANDOM}${RANDOM}${RANDOM}" | cut -b1-5)"
 
rm -f ${ramloc}/${prefix}_md_proc_*
 
for ((i=0;i<${rounds};i++)); do
 
  for ((i=0;i<${threads};i++)); do
 
    if [ ! -r ${ramloc}/${prefix}_md_proc_${i} ]; then  # Thread idle
 
      touch ${ramloc}/${prefix}_md_proc_${i}  # Thread busy
 
      insert_rows ${i} &
 
      count=$[ ${count} + 1 ]
 
      if [ $[ ${count} % 100 ] -eq 0 ]; then  # Limit disk I/O, check once every new 100 threads
 
        echo "Count: ${count}" | tee lastcount.log
 
        TAIL="$(tail -n10 ${errorlog} | tr -d '\n')"
 
        if [[ "${TAIL}" == *"ERROR"* ]]; then
 
          echo '*** Error found:'
 
          grep -i 'ERROR' log/master.err
 
          abort
 
        elif [[ "${TAIL}" == *"down complete"* ]]; then
 
          echo '*** Server shutdown'
 
          abort
 
        elif ! ${client}-admin ping -u ${user} -S ${socket} > /dev/null 2>&1; then
 
          echo '*** Server gone (killed/crashed)'
 
          abort
 
        fi
 
      fi
 
    fi
 
  done
 
done

Leads to:

10.6.15 b102872ad50cce5959ad95369740766d14e9e48c (Debug)

 
2023-07-28 15:56:32 0 [Note] /test/MD280723-mariadb-10.6.15-linux-x86_64-dbg/bin/mariadbd: ready for connections.
 
Version: '10.6.15-MariaDB-debug'  socket: '/test/MD280723-mariadb-10.6.15-linux-x86_64-dbg/socket.sock'  port: 10673  MariaDB Server
 
2023-07-28 15:56:40 1507 [Note] InnoDB: Number of pools: 2
 
mariadbd: /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:2572: dberr_t btr_attach_half_pages(ulint, dict_index_t*, buf_block_t*, const rec_t*, buf_block_t*, ulint, mtr_t*): Assertion `mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK)' failed.

10.6.15 b102872ad50cce5959ad95369740766d14e9e48c (Debug)

 
Core was generated by `/test/MD280723-mariadb-10.6.15-linux-x86_64-dbg/bin/mariadbd --no-defaults --co'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22708999960128)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x14a759e03640 (LWP 201344))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22708999960128) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=22708999960128) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=22708999960128, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x000014a8d5a42476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x000014a8d5a287f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x000014a8d5a2871b in __assert_fail_base (fmt=0x14a8d5bdd150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5628735a0648 "mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK)", file=0x5628735a0278 "/test/10.6_dbg/storage/innobase/btr/btr0btr.cc", line=2572, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x000014a8d5a39e96 in __GI___assert_fail (assertion=0x5628735a0648 "mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK)", file=0x5628735a0278 "/test/10.6_dbg/storage/innobase/btr/btr0btr.cc", line=2572, function=0x5628735a2840 "dberr_t btr_attach_half_pages(ulint, dict_index_t*, buf_block_t*, const rec_t*, buf_block_t*, ulint, mtr_t*)") at ./assert/assert.c:101
 
#7  0x0000562872fff9e2 in btr_attach_half_pages (mtr=0x14a759e00d70, direction=112, new_block=0x14a8c016cfb0, split_rec=0x14a8c5fa5d4f "\204|\273р", block=0x14a8c01309a0, index=0x14a8900669b0, flags=7) at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:2572
 
#8  btr_page_split_and_insert (flags=flags@entry=7, cursor=cursor@entry=0x14a759dffcd0, offsets=offsets@entry=0x14a759dffcc8, heap=heap@entry=0x14a759dffcc0, tuple=tuple@entry=0x14a58816cf30, n_ext=0, mtr=0x14a759e00d70, err=0x14a759dffc3c) at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:3120
 
#9  0x000056287301a5d6 in btr_cur_pessimistic_insert (flags=flags@entry=7, cursor=cursor@entry=0x14a759dffcd0, offsets=offsets@entry=0x14a759dffcc8, heap=heap@entry=0x14a759dffcc0, entry=entry@entry=0x14a58816cf30, rec=rec@entry=0x14a759dffcb8, big_rec=0x14a759dffcb0, n_ext=<optimized out>, thr=0x0, mtr=0x14a759e00d70) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:2689
 
#10 0x0000562872ff3ee3 in btr_insert_on_non_leaf_level (flags=7, flags@entry=0, index=0x14a8900669b0, level=level@entry=1, tuple=0x14a58816cf30, mtr=mtr@entry=0x14a759e00d70) at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:2474
 
#11 0x0000562872fff659 in btr_insert_into_right_sibling (mtr=0x14a759e00d70, n_ext=0, tuple=0x14a5100afa38, heap=<optimized out>, offsets=0x14a759e00420, cursor=0x14a759e004a0, flags=0) at /test/10.6_dbg/storage/innobase/include/btr0cur.h:744
 
#12 btr_page_split_and_insert (flags=flags@entry=0, cursor=cursor@entry=0x14a759e004a0, offsets=offsets@entry=0x14a759e00420, heap=heap@entry=0x14a759e00418, tuple=tuple@entry=0x14a5100afa38, n_ext=0, mtr=0x14a759e00d70, err=0x14a759e0036c) at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:2997
 
#13 0x000056287301a5d6 in btr_cur_pessimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x14a759e004a0, offsets=offsets@entry=0x14a759e00420, heap=heap@entry=0x14a759e00418, entry=entry@entry=0x14a5100afa38, rec=rec@entry=0x14a759e00530, big_rec=0x14a759e00870, n_ext=<optimized out>, thr=0x14a54c1af1f8, mtr=0x14a759e00d70) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:2689
 
#14 0x0000562872f240c2 in row_ins_sec_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=BTR_INSERT_TREE, index=index@entry=0x14a8900669b0, offsets_heap=<optimized out>, offsets_heap@entry=0x14a58816ce80, heap=heap@entry=0x14a588057870, entry=entry@entry=0x14a5100afa38, trx_id=<optimized out>, thr=<optimized out>) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3143
 
#15 0x0000562872f24a22 in row_ins_sec_index_entry (index=index@entry=0x14a8900669b0, entry=entry@entry=0x14a5100afa38, thr=thr@entry=0x14a54c1af1f8, check_foreign=check_foreign@entry=true) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3333
 
#16 0x0000562872f2935a in row_ins_index_entry (thr=0x14a54c1af1f8, entry=0x14a5100afa38, index=0x14a8900669b0) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3367
 
#17 row_ins_index_entry_step (thr=0x14a54c1af1f8, node=0x14a54c1aefc0) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3533
 
#18 row_ins (thr=0x14a54c1af1f8, node=0x14a54c1aefc0) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3658
 
#19 row_ins_step (thr=thr@entry=0x14a54c1af1f8) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3787
 
#20 0x0000562872f48998 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x14a73c03c288 "\377\336\306|\004", prebuilt=0x14a54c1aeac0, ins_mode=ins_mode@entry=ROW_INS_NORMAL) at /test/10.6_dbg/storage/innobase/row/row0mysql.cc:1314
 
#21 0x0000562872df8fe3 in ha_innobase::write_row (this=0x14a54c184270, record=0x14a73c03c288 "\377\336\306|\004") at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7917
 
#22 0x0000562872adf167 in handler::ha_write_row (this=0x14a54c184270, buf=0x14a73c03c288 "\377\336\306|\004") at /test/10.6_dbg/sql/handler.cc:7629
 
#23 0x00005628727eb899 in write_record (thd=thd@entry=0x14a588000d58, table=table@entry=0x14a73c0246f8, info=info@entry=0x14a759e01a80, sink=sink@entry=0x0) at /test/10.6_dbg/sql/sql_insert.cc:2157
 
#24 0x00005628727f4b6e in mysql_insert (thd=thd@entry=0x14a588000d58, table_list=<optimized out>, fields=@0x14a588005e10: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14a588013a00, last = 0x14a588013a00, elements = 1}, <No data fields>}, values_list=@0x14a588005e58: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14a588013f70, last = 0x14a588013f70, elements = 1}, <No data fields>}, update_fields=@0x14a588005e40: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x562873c22700 <end_of_list>, last = 0x14a588005e40, elements = 0}, <No data fields>}, update_values=@0x14a588005e28: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x562873c22700 <end_of_list>, last = 0x14a588005e28, elements = 0}, <No data fields>}, duplic=DUP_ERROR, ignore=false, result=0x0) at /test/10.6_dbg/sql/sql_insert.cc:1129
 
#25 0x000056287282d580 in mysql_execute_command (thd=thd@entry=0x14a588000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.6_dbg/sql/sql_parse.cc:4570
 
#26 0x0000562872832eac in mysql_parse (thd=thd@entry=0x14a588000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14a759e02210) at /test/10.6_dbg/sql/sql_parse.cc:8041
 
#27 0x0000562872835040 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14a588000d58, packet=packet@entry=0x14a58817a539 "INSERT INTO t1 (c2) VALUES (0)", packet_length=packet_length@entry=30, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:241
 
#28 0x0000562872836f1c in do_command (thd=0x14a588000d58, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1409
 
#29 0x000056287296d8e2 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x56287579a348, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1416
 
#30 0x000056287296db41 in handle_one_connection (arg=0x56287579a348) at /test/10.6_dbg/sql/sql_connect.cc:1318
 
#31 0x000014a8d5a94b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#32 0x000014a8d5b26a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81



 Comments   
Comment by Marko Mäkelä [ 2023-08-01 ]

10.6 b102872ad50cce5959ad95369740766d14e9e48c

 
(gdb) frame 5
 
#5  0x0000562872fff9e2 in btr_attach_half_pages (mtr=0x14a759e00d70, direction=112, new_block=0x14a8c016cfb0, split_rec=0x14a8c5fa5d4f "\204|\273р", block=0x14a8c01309a0, index=0x14a8900669b0, flags=7)
 
    at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:2572
 
2572	/test/10.6_dbg/storage/innobase/btr/btr0btr.cc: Tiedostoa tai hakemistoa ei ole.
 
(gdb) p mtr.m_memo
 
$1 = {<small_vector_base> = {BeginX = 0x14a58816cc78, Size = 17, Capacity = 32}, small = {{object = 0x8f8f8f8f8f8f8f8f, type = 2408550287} <repeats 16 times>}}
 
(gdb) p *(mtr_memo_slot_t*)mtr.m_memo.BeginX@17
 
$2 = {{object = 0x14a890066b28, type = MTR_MEMO_SX_LOCK}, {object = 0x14a8c013e1c0, type = MTR_MEMO_PAGE_X_MODIFY}, {object = 0x14a8c016cfb0, type = MTR_MEMO_PAGE_X_MODIFY}, {object = 0x14a8c017dfe0, 
    type = MTR_MEMO_PAGE_X_FIX}, {object = 0x14a8c00fcc10, type = MTR_MEMO_PAGE_X_FIX}, {object = 0x14a8c0146490, type = MTR_MEMO_PAGE_X_MODIFY}, {object = 0x14a890063800, type = MTR_MEMO_SPACE_X_LOCK}, {
 
    object = 0x14a8c00e8570, type = MTR_MEMO_PAGE_SX_FIX}, {object = 0x14a8c0146490, type = MTR_MEMO_PAGE_X_FIX}, {object = 0x14a8c01309a0, type = MTR_MEMO_PAGE_X_MODIFY}, {object = 0x14a8c00d0ad0, 
    type = MTR_MEMO_PAGE_SX_MODIFY}, {object = 0x14a8c00e8570, type = MTR_MEMO_PAGE_SX_FIX}, {object = 0x14a8c00b0060, type = MTR_MEMO_PAGE_SX_MODIFY}, {object = 0x14a8c00d0ad0, type = MTR_MEMO_PAGE_SX_FIX}, {
 
    object = 0x14a8c00b0060, type = MTR_MEMO_PAGE_SX_FIX}, {object = 0x14a8c00e8570, type = MTR_MEMO_PAGE_SX_FIX}, {object = 0x14a8c00b0060, type = MTR_MEMO_PAGE_SX_FIX}}
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[1].object)->id_.m_id
 
$6 = 0x500000004
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[2].object)->id_.m_id
 
$7 = 0x5000b91d2
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[3].object)->id_.m_id
 
$8 = 0x50009f364
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[4].object)->id_.m_id
 
$9 = 0x50009f363
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[5].object)->id_.m_id
 
$10 = 0x50009f366
 
(gdb) p/x ((fil_space_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[6].object)->id
 
$12 = 0x5
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[7].object)->id_.m_id
 
$13 = 0x500000000
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[8].object)->id_.m_id
 
$14 = 0x50009f366
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[9].object)->id_.m_id
 
$15 = 0x5000b91d3
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[10].object)->id_.m_id
 
$16 = 0x500000002
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[11].object)->id_.m_id
 
$17 = 0x500000000
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[12].object)->id_.m_id
 
$18 = 0x5000b9000
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[13].object)->id_.m_id
 
$19 = 0x500000002
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[14].object)->id_.m_id
 
$20 = 0x5000b9000
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[15].object)->id_.m_id
 
$21 = 0x500000000
 
(gdb) p/x ((buf_page_t*)((mtr_memo_slot_t*)mtr.m_memo.BeginX)[16].object)->id_.m_id
 
$22 = 0x5000b9000

We can observe that there are some redundant entries in mtr_t::m_memo for some index pages.

This is the secondary index u1 of the table t1. We are holding latches on the index root page (page number 4, PAGE_LEVEL 2) as well as some pages at level 1 and 0. We are trying to acquire a latch on the level-1 page 0x5000b91d1. That counts as lock order inversion, because we are already holding latches on level-0 pages.

The fix of MDEV-29835 fails to escalate to an exclusive index latch here. The debug assertion is catching a potential deadlock of threads due to lock order inversion.

I think that instead of using ROW_FORMAT=COMPRESSED, you should try to reproduce this with innodb_limit_optimistic_insert_debug=2 on an optimized debug build.

Generated at Thu Feb 08 10:26:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.