MDEV-18706 ER_LOCK_DEADLOCK on concurrent read and insert into already locked gap

midenok / mariadb

MariaDB server is a community developed fork of MySQL server. Started by core members of the original MySQL team, MariaDB actively works with outside developers to deliver the most featureful, stable, and sanely licensed open SQL server in the industry.

GNU General Public License v2.0

0 stars 0 forks source link

MDEV-18706 ER_LOCK_DEADLOCK on concurrent read and insert into already locked gap #56

Open midenok opened 5 years ago

midenok commented 5 years ago

Reproduce

--source include/have_innodb.inc
--source include/have_partition.inc
--let $i= 0
while ($i < 40)
{
--inc $i
create table t1 (pk int, c char(32), primary key (pk)) engine=innodb
with system versioning
partition by hash(pk) partitions 2;
insert into t1 values (1,'foo'),(2,'bar');
handler t1 open as h;
--connect (con1,localhost,root,,test)
--send
update t1 set c= 4;
--connection default
# Two statements below are not required for the scenario,
# but apparently they help with the timing, it fails better with them
--error ER_UNKNOWN_TABLE
handler unknown_handler close;
--error ER_NO_SUCH_TABLE
handler unknown_table open;
--error 0, ER_LOCK_DEADLOCK
handler h read `primary` prev;
show engine innodb status;
# Cleanup
--connection con1
--reap
--disconnect con1
--connection default
handler h close;
drop table t1;
}

Result

------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-07-24 15:30:02 0x7fbae2eec300
*** (1) TRANSACTION:
TRANSACTION 421915840227616, ACTIVE 0 sec starting index read
mysql tables in use 2, locked 2
LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 9, OS thread handle 140440650195712, query id 446 localhost root Init
handler h read `primary` prev

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 81 page no 3 n bits 72 index PRIMARY of table `test`.`t1` /* Partition `p0` */ trx id 421915840227616 lock mode S waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
0: len 4; hex 80000002; asc     ;;
1: len 7; hex 7fffffff0f423f; asc      B?;;
2: len 6; hex 00000000028a; asc       ;;
3: len 7; hex 03000001370440; asc     7 @;;
4: len 30; hex 342020202020202020202020202020202020202020202020202020202020; asc 4                             ; (total 32 bytes);
5: len 7; hex 5d384f4a02efda; asc ]8OJ   ;;

*** (2) TRANSACTION:
TRANSACTION 650, ACTIVE 0 sec inserting
mysql tables in use 2, locked 2
3 lock struct(s), heap size 1160, 2 row lock(s), undo log entries 1
MySQL thread id 48, OS thread handle 140440647942912, query id 443 localhost root Updating
update t1 set c= 4

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 81 page no 3 n bits 72 index PRIMARY of table `test`.`t1` /* Partition `p0` */ trx id 650 lock_mode X
Record lock, heap no 2 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
0: len 4; hex 80000002; asc     ;;
1: len 7; hex 7fffffff0f423f; asc      B?;;
2: len 6; hex 00000000028a; asc       ;;
3: len 7; hex 03000001370440; asc     7 @;;
4: len 30; hex 342020202020202020202020202020202020202020202020202020202020; asc 4                             ; (total 32 bytes);
5: len 7; hex 5d384f4a02efda; asc ]8OJ   ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 81 page no 3 n bits 72 index PRIMARY of table `test`.`t1` /* Partition `p0` */ trx id 650 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
0: len 4; hex 80000002; asc     ;;
1: len 7; hex 7fffffff0f423f; asc      B?;;
2: len 6; hex 00000000028a; asc       ;;
3: len 7; hex 03000001370440; asc     7 @;;
4: len 30; hex 342020202020202020202020202020202020202020202020202020202020; asc 4                             ; (total 32 bytes);
5: len 7; hex 5d384f4a02efda; asc ]8OJ   ;;

*** WE ROLL BACK TRANSACTION (1)

On HANDLER

HANDLER is a somewhat low-level statement. For example, it does not provide consistency. That is, HANDLER ... OPEN does not take a snapshot of the table, and does not lock the table. This means that after a HANDLER ... OPEN statement is issued, table data can be modified (by the current session or other sessions) and these modifications might be only partially visible to HANDLER ... NEXT or HANDLER ... PREV scans.

Deadlock possibilities

Multiple index

Range lock + Gap lock

Other multiple locks of different type?

Tips

mtr option: --mysqld=--debug=d,ib_lock

midenok commented 5 years ago

Bad

Transaction 1

#6  0x0000000001fad7fc in lock_wait_suspend_thread (thr=0x6210000bec90) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0wait.cc:355
#7  0x00000000021c5ad8 in row_mysql_handle_errors (new_err=0x7fffe0f45880, trx=0x7fffedac2920, thr=0x6210000bec90, savept=0x0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:740
#8  0x000000000227bb7f in row_search_mvcc (buf=0x60c00003178a '\276' <repeats 51 times>, "\001", mode=PAGE_CUR_L, prebuilt=0x6210000be188, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5635
#9  0x0000000001d98330 in ha_innobase::index_read (this=0x61c0000550a8, buf=0x60c00003178a '\276' <repeats 51 times>, "\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_BEFORE_KEY) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9336
#10 0x0000000001d9adc3 in ha_innobase::index_last (this=0x61c0000550a8, buf=0x60c00003178a '\276' <repeats 51 times>, "\001") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9733
#11 0x000000000162b0cf in handler::ha_index_last (this=0x61c0000550a8, buf=0x60c00003178a '\276' <repeats 51 times>, "\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:3002
#12 0x0000000002f06378 in ha_partition::handle_ordered_index_scan (this=0x61d0002828a8, buf=0x6190000fb9d8 "\377", reverse_order=false) at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:7522
#13 0x0000000002f0874f in ha_partition::common_first_last (this=0x61d0002828a8, buf=0x6190000fb9d8 "\377") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:5750
#14 0x0000000002f0895d in ha_partition::index_last (this=0x61d0002828a8, buf=0x6190000fb9d8 "\377") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:5725
#15 0x000000000162afc0 in handler::ha_index_last (this=0x61d0002828a8, buf=0x6190000fb9d8 "\377") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:3002
#16 0x0000000000b1317c in mysql_ha_read (thd=0x62b00009a208, tables=0x62b0000a13d8, mode=RLAST, keyname=0x62b0000a1aa8 "primary", key_expr=0x62b0000a2068, ha_rkey_mode=HA_READ_KEY_EXACT, cond=0x0, select_limit_cnt=1, offset_limit_cnt=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_handler.cc:928
#17 0x0000000000c18065 in mysql_execute_command (thd=0x62b00009a208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:5574
#18 0x0000000000bf7415 in mysql_parse (thd=0x62b00009a208, rawbuf=0x62b0000a1228 "handler h read `primary` prev", length=29, parser_state=0x7fffe0f4fa80, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

frame 7

(gdb) p trx
$43 = (trx_t *) 0x7fffedac2920

frame 9

(gdb) p index
$22 = (dict_index_t *) 0x6190000f8d08

Transaction 2

Deadlock on history insert:

#4  0x0000000001fafed2 in lock_wait_release_thread_if_suspended (thr=0x621000138090) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0wait.cc:452
#5  0x0000000001f88529 in lock_cancel_waiting_and_release (lock=0x7fffedac2ba0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6218
#6  0x0000000001f90ce9 in DeadlockChecker::trx_rollback (this=0x7fffe0e9a480) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6986
#7  0x0000000001f7171f in DeadlockChecker::check_and_resolve (lock=0x7fffedac3cb8, trx=0x7fffedac3a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:7053
#8  0x0000000001f6fa23 in lock_rec_enqueue_waiting (type_mode=2563, block=0x7fffed253a60, heap_no=2, index=0x619000139808, thr=0x6210001424b0, prdt=0x0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1737
#9  0x0000000001f8258d in lock_rec_insert_check_and_lock (flags=0, rec=0x7fffed47c063 "infimum", block=0x7fffed253a60, index=0x619000139808, thr=0x6210001424b0, mtr=0x7fffe0e9c4a0, inherit=0x7fffe0e9b740) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5341
#10 0x00000000024997b1 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7fffe0e9c340, entry=0x61700003b588, thr=0x6210001424b0, mtr=0x7fffe0e9c4a0, inherit=0x7fffe0e9b740) at /home/midenok/src/mariadb/trunk/src/storage/innobase/btr/btr0cur.cc:3247
#11 0x00000000024967bd in btr_cur_optimistic_insert (flags=0, cursor=0x7fffe0e9c340, offsets=0x7fffe0e9cde0, heap=0x7fffe0e9ca20, entry=0x61700003b588, rec=0x7fffe0e9ce40, big_rec=0x7fffe0e9c480, n_ext=0, thr=0x6210001424b0, mtr=0x7fffe0e9c4a0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/btr/btr0cur.cc:3483
#12 0x00000000021621cc in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x619000139808, n_uniq=2, entry=0x61700003b588, n_ext=0, thr=0x6210001424b0, dup_chk_only=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:2747
#13 0x000000000216b695 in row_ins_clust_index_entry (index=0x619000139808, entry=0x61700003b588, thr=0x6210001424b0, n_ext=0, dup_chk_only=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3271
#14 0x000000000217ddff in row_ins_index_entry (index=0x619000139808, entry=0x61700003b588, thr=0x6210001424b0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3398
#15 0x000000000217c242 in row_ins_index_entry_step (node=0x6210001421e0, thr=0x6210001424b0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3567
#16 0x000000000216e56b in row_ins (node=0x6210001421e0, thr=0x6210001424b0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3710
#17 0x000000000216d9dd in row_ins_step (thr=0x6210001424b0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3955
#18 0x00000000021cdc2c in row_insert_for_mysql (mysql_rec=0x6190000b63d8 "\375\002", prebuilt=0x621000141588, ins_mode=ROW_INS_NORMAL) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:1459
#19 0x0000000001d8c0f6 in ha_innobase::write_row (this=0x61c0000720a8, record=0x6190000b63d8 "\375\002") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:8078
#20 0x000000000164ee0e in handler::ha_write_row (this=0x61c0000720a8, buf=0x6190000b63d8 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#21 0x0000000002ef1186 in ha_partition::write_row (this=0x61d0003318a8, buf=0x6190000b63d8 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:4331
#22 0x000000000164eca9 in handler::ha_write_row (this=0x61d0003318a8, buf=0x6190000b63d8 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#23 0x0000000000b2f302 in TABLE::vers_insert_history_row (this=0x620000062088) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1680
#24 0x0000000000fb8f48 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b64c0, select_lex=0x62b0000b3920, values=..., limit=18446744073709551615, ignore=false, found_return=0x7fffe0ea2a40, updated_return=0x7fffe0ea2a60) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:1061
#25 0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#26 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b63b8 "update t1 set c= 4", length=18, parser_state=0x7fffe0ea7a80, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

frame 4

431     /********************************************************************//**
432     Releases a user OS thread waiting for a lock to be released, if the
433     thread is already suspended. */
434     void
435     lock_wait_release_thread_if_suspended(
436     /*==================================*/
437             que_thr_t*      thr)    /*!< in: query thread associated with the
438                                     user OS thread   */
439     {
440             ut_ad(lock_mutex_own());
441             ut_ad(trx_mutex_own(thr_get_trx(thr)));
442
443             /* We own both the lock mutex and the trx_t::mutex but not the
444             lock wait mutex. This is OK because other threads will see the state
445             of this slot as being in use and no other thread can change the state
446             of the slot to free unless that thread also owns the lock mutex. */
447
448             if (thr->slot != NULL && thr->slot->in_use && thr->slot->thr == thr) {
449                     trx_t*  trx = thr_get_trx(thr);
450
451                     if (trx->lock.was_chosen_as_deadlock_victim) {
452                             ut_ad(0);
453                             trx->error_state = DB_DEADLOCK;
454                             trx->lock.was_chosen_as_deadlock_victim = false;
455                     }
456
457                     os_event_set(thr->slot->event);
458             }
459     }

frame 7

(gdb) p trx
$41 = (trx_t *) 0x7fffedac3a38

(gdb) p victim_trx
$42 = (const trx_t *) 0x7fffedac2920

(gdb) p *trx->lock.trx_locks.start
$45 = {
  trx = 0x7fffedac3a38,
  trx_locks = {
    prev = 0x0,
    next = 0x7fffedac3b60
  },
  index = 0x0,
  hash = 0x0,
  requested_time = 0,
  wait_time = 0,
  un_member = {
    tab_lock = {
      table = 0x6190000f7408,
      locks = {
        prev = 0x7fffedac3508,
        next = 0x0
      }
    },
    rec_lock = {
      space = 1012744,
      page_no = 24976,
      n_bits = 3987485960
    }
  },
  type_mode = 17
}

(gdb) p *victim_trx->lock.trx_locks.start
$29 = {
  trx = 0x7fffedac2920, 
  trx_locks = {
    prev = 0x0, 
    next = 0x7fffedac2a48
  }, 
  index = 0x0, 
  hash = 0x0, 
  requested_time = 0, 
  wait_time = 0, 
  un_member = {
    tab_lock = {
      table = 0x6190000f7408, 
      locks = {
        prev = 0x0, 
        next = 0x7fffedac4620
      }
    }, 
    rec_lock = {
      space = 1012744, 
      page_no = 24976, 
      n_bits = 0
    }
  }, 
  type_mode = 16
}

frame 10

(gdb) p index
$23 = (dict_index_t *) 0x6190000f8d08
(gdb) p *index->table->locks.start
$31 = {
  trx = 0x7fffedac2920,
  trx_locks = {
    prev = 0x0,
    next = 0x7fffedac2a48
  },
  index = 0x0,
  hash = 0x0,
  requested_time = 0,
  wait_time = 0,
  un_member = {
    tab_lock = {
      table = 0x6190000f7408,
      locks = {
        prev = 0x0,
        next = 0x7fffedac4620
      }
    },
    rec_lock = {
      space = 1012744,
      page_no = 24976,
      n_bits = 0
    }
  },
  type_mode = 16
}

dict_index_t pointer is same for both threads.

midenok commented 5 years ago

Good: INSERT

1. IX lock acquired

#0  lock_table (flags=0, table=0x6190000c7708, mode=LOCK_IX, thr=0x62000003f880) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:3873
#1  0x000000000216d5ec in row_ins_step (thr=0x62000003f880) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3918
#2  0x00000000021cdc2c in row_insert_for_mysql (mysql_rec=0x6190000c99b8 "\375\001", prebuilt=0x62000003f108, ins_mode=ROW_INS_NORMAL) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:1459
#3  0x0000000001d8c0f6 in ha_innobase::write_row (this=0x61c00002d0a8, record=0x6190000c99b8 "\375\001") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:8078
#4  0x000000000164ee0e in handler::ha_write_row (this=0x61c00002d0a8, buf=0x6190000c99b8 "\375\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#5  0x0000000000b2a930 in write_record (thd=0x62b0000af208, table=0x62000003e088, info=0x7fffd05f0720) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:2053
#6  0x0000000000b1f00a in mysql_insert (thd=0x62b0000af208, table_list=0x62b0000b6338, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1075

2. IX lock freed

#0  ut_list_remove<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> lock_table_t::*>, TableLockGetNode> (list=..., node=..., get_node=...) at /home/midenok/src/mariadb/trunk/src/storage/innobase/include/ut0lst.h:359
#1  0x0000000001fa2846 in ut_list_remove<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> lock_table_t::*>, TableLockGetNode> (list=..., elem=0x7fffe9773620, get_node=...) at /home/midenok/src/mariadb/trunk/src/storage/innobase/include/ut0lst.h:373
#2  0x0000000001f955ae in lock_table_remove_low (lock=0x7fffe9773620) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:3714
#3  0x0000000001f8952c in lock_table_dequeue (in_lock=0x7fffe9773620) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:4023
#4  0x0000000001f8a859 in lock_release (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:4324
#5  0x0000000001f8a34e in lock_trx_release_locks (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6325
#6  0x00000000023ecd7e in trx_commit_in_memory (trx=0x7fffe9772a38, mtr=0x7fffd05ee560) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1338
#7  0x00000000023eaf44 in trx_commit_low (trx=0x7fffe9772a38, mtr=0x7fffd05ee560) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1552
#8  0x00000000023eeee4 in trx_commit (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1576
#9  0x00000000023f1756 in trx_commit_for_mysql (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1722
#10 0x0000000001d7723b in innobase_commit_low (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:4416
#11 0x0000000001dd952e in innobase_commit_ordered_2 (trx=0x7fffe9772a38, thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:4538
#12 0x0000000001ddb854 in innobase_commit_ordered (hton=0x614000002048, thd=0x62b0000af208, all=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:4598
#13 0x00000000019e670b in TC_LOG::run_commit_ordered (this=0x52b0be0 <mysql_bin_log>, thd=0x62b0000af208, all=false) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:8949
#14 0x00000000019e5e68 in MYSQL_BIN_LOG::trx_group_commit_leader (this=0x52b0be0 <mysql_bin_log>, leader=0x7fffd05efd20) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:8183
#15 0x00000000019df696 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x52b0be0 <mysql_bin_log>, entry=0x7fffd05efd20) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7772
#16 0x00000000019df44d in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x52b0be0 <mysql_bin_log>, thd=0x62b0000af208, cache_mngr=0x61b00002f488, end_ev=0x7fffd05f0300, all=false, using_stmt_cache=true, using_trx_cache=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7427
#17 0x00000000019fa9f4 in binlog_flush_cache (thd=0x62b0000af208, cache_mngr=0x61b00002f488, end_ev=0x7fffd05f0300, all=false, using_stmt=true, using_trx=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1785
#18 0x00000000019f3fee in binlog_commit_flush_xid_caches (thd=0x62b0000af208, cache_mngr=0x61b00002f488, all=false, xid=14) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1893
#19 0x00000000019f38da in MYSQL_BIN_LOG::log_and_order (this=0x52b0be0 <mysql_bin_log>, thd=0x62b0000af208, xid=14, all=false, need_prepare_ordered=false, need_commit_ordered=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:9732
#20 0x0000000001619af2 in ha_commit_trans (thd=0x62b0000af208, all=false) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:1623
#21 0x000000000118cc52 in trans_commit_stmt (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/transaction.cc:436
#22 0x0000000000c1cc6f in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6139
#23 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "insert into n1 values (1)", length=25, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

Good: UPDATE

1. IX lock acquired

#0  lock_table (flags=0, table=0x619000020908, mode=LOCK_IX, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:3873
#1  0x0000000002273234 in row_search_mvcc (buf=0x6190000b22b8 "\377", mode=PAGE_CUR_G, prebuilt=0x620000031108, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:4515
#2  0x0000000001d98330 in ha_innobase::index_read (this=0x61c0000208a8, buf=0x6190000b22b8 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9336
#3  0x0000000001d9aac3 in ha_innobase::index_first (this=0x61c0000208a8, buf=0x6190000b22b8 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9710
#4  0x0000000001d9b2ce in ha_innobase::rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9803
#5  0x000000000162522d in handler::ha_rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\377") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#6  0x0000000001b927b0 in rr_sequential (info=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#7  0x00000000009e4e36 in READ_RECORD::read_record (this=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#8  0x0000000000fb8192 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b6330, select_lex=0x62b0000b3920, values=..., limit=18446744073709551615, ignore=false, found_return=0x7fffd05f1f20, updated_return=0x7fffd05f1f40) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:958
#9  0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#10 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

2. Rec lock

#0  lock_rec_lock (impl=false, mode=3, block=0x7fffe16ab1c8, heap_no=2, index=0x619000021308, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1939
#1  0x0000000001f86f86 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffe16ab1c8, rec=0x7fffe218807e "", index=0x619000021308, offsets=0x7fffd05ec6f0, mode=LOCK_X, gap_mode=0, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5855
#2  0x000000000228238a in sel_set_rec_lock (pcur=0x6200000312d0, rec=0x7fffe218807e "", index=0x619000021308, offsets=0x7fffd05ec6f0, mode=3, type=0, thr=0x6200000317d8, mtr=0x7fffd05ec150) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:1262
#3  0x0000000002277783 in row_search_mvcc (buf=0x6190000b22b8 "\377", mode=PAGE_CUR_G, prebuilt=0x620000031108, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5014
#4  0x0000000001d98330 in ha_innobase::index_read (this=0x61c0000208a8, buf=0x6190000b22b8 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9336
#5  0x0000000001d9aac3 in ha_innobase::index_first (this=0x61c0000208a8, buf=0x6190000b22b8 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9710
#6  0x0000000001d9b2ce in ha_innobase::rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9803
#7  0x000000000162522d in handler::ha_rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\377") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#8  0x0000000001b927b0 in rr_sequential (info=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#9  0x00000000009e4e36 in READ_RECORD::read_record (this=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#10 0x0000000000fb8192 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b6330, select_lex=0x62b0000b3920, values=..., limit=18446744073709551615, ignore=false, found_return=0x7fffd05f1f20, updated_return=0x7fffd05f1f40) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:958
#11 0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#12 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

3. Rec lock

#0  lock_rec_lock (impl=false, mode=3, block=0x7fffe16ab1c8, heap_no=3, index=0x619000021308, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1939
#1  0x0000000001f86f86 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffe16ab1c8, rec=0x7fffe218809b "", index=0x619000021308, offsets=0x7fffd05ec990, mode=LOCK_X, gap_mode=0, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5855
#2  0x000000000228238a in sel_set_rec_lock (pcur=0x6200000312d0, rec=0x7fffe218809b "", index=0x619000021308, offsets=0x7fffd05ec990, mode=3, type=0, thr=0x6200000317d8, mtr=0x7fffd05ec3f0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:1262
#3  0x0000000002277783 in row_search_mvcc (buf=0x6190000b22b8 "\375\003", mode=PAGE_CUR_G, prebuilt=0x620000031108, match_mode=0, direction=1) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5014
#4  0x0000000001d99c8b in ha_innobase::general_fetch (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003", direction=1, match_mode=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9601
#5  0x0000000001d9b380 in ha_innobase::rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9811
#6  0x000000000162522d in handler::ha_rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#7  0x0000000001b927b0 in rr_sequential (info=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#8  0x00000000009e4e36 in READ_RECORD::read_record (this=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#9  0x0000000000fb8192 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b6330, select_lex=0x62b0000b3920, values=..., limit=18446744073709551614, ignore=false, found_return=0x7fffd05f1f20, updated_return=0x7fffd05f1f40) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:958
#10 0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#11 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

4. Rec lock

#0  lock_rec_lock (impl=false, mode=3, block=0x7fffe16ab1c8, heap_no=4, index=0x619000021308, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1939
#1  0x0000000001f86f86 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffe16ab1c8, rec=0x7fffe21880b8 "", index=0x619000021308, offsets=0x7fffd05ec990, mode=LOCK_X, gap_mode=0, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5855
#2  0x000000000228238a in sel_set_rec_lock (pcur=0x6200000312d0, rec=0x7fffe21880b8 "", index=0x619000021308, offsets=0x7fffd05ec990, mode=3, type=0, thr=0x6200000317d8, mtr=0x7fffd05ec3f0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:1262
#3  0x0000000002277783 in row_search_mvcc (buf=0x6190000b22b8 "\375\003", mode=PAGE_CUR_G, prebuilt=0x620000031108, match_mode=0, direction=1) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5014
#4  0x0000000001d99c8b in ha_innobase::general_fetch (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003", direction=1, match_mode=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9601
#5  0x0000000001d9b380 in ha_innobase::rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9811
#6  0x000000000162522d in handler::ha_rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#7  0x0000000001b927b0 in rr_sequential (info=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#8  0x00000000009e4e36 in READ_RECORD::read_record (this=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#9  0x0000000000fb8192 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b6330, select_lex=0x62b0000b3920, values=..., limit=18446744073709551613, ignore=false, found_return=0x7fffd05f1f20, updated_return=0x7fffd05f1f40) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:958
#10 0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#11 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

5. Rec lock

#0  lock_rec_lock (impl=false, mode=3, block=0x7fffe16ab1c8, heap_no=5, index=0x619000021308, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1939
#1  0x0000000001f86f86 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffe16ab1c8, rec=0x7fffe21880d5 "", index=0x619000021308, offsets=0x7fffd05ec990, mode=LOCK_X, gap_mode=0, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5855
#2  0x000000000228238a in sel_set_rec_lock (pcur=0x6200000312d0, rec=0x7fffe21880d5 "", index=0x619000021308, offsets=0x7fffd05ec990, mode=3, type=0, thr=0x6200000317d8, mtr=0x7fffd05ec3f0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:1262
#3  0x0000000002277783 in row_search_mvcc (buf=0x6190000b22b8 "\375\003", mode=PAGE_CUR_G, prebuilt=0x620000031108, match_mode=0, direction=1) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5014
#4  0x0000000001d99c8b in ha_innobase::general_fetch (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003", direction=1, match_mode=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9601
#5  0x0000000001d9b380 in ha_innobase::rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9811
#6  0x000000000162522d in handler::ha_rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#7  0x0000000001b927b0 in rr_sequential (info=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#8  0x00000000009e4e36 in READ_RECORD::read_record (this=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#9  0x0000000000fb8192 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b6330, select_lex=0x62b0000b3920, values=..., limit=18446744073709551612, ignore=false, found_return=0x7fffd05f1f20, updated_return=0x7fffd05f1f40) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:958
#10 0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#11 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

6. Rec lock

#0  lock_rec_lock (impl=false, mode=3, block=0x7fffe16ab1c8, heap_no=1, index=0x619000021308, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1939
#1  0x0000000001f86f86 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffe16ab1c8, rec=0x7fffe2188070 "supremum", index=0x619000021308, offsets=0x7fffd05ec990, mode=LOCK_X, gap_mode=0, thr=0x6200000317d8) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5855
#2  0x000000000228238a in sel_set_rec_lock (pcur=0x6200000312d0, rec=0x7fffe2188070 "supremum", index=0x619000021308, offsets=0x7fffd05ec990, mode=3, type=0, thr=0x6200000317d8, mtr=0x7fffd05ec3f0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:1262
#3  0x0000000002274c09 in row_search_mvcc (buf=0x6190000b22b8 "\375\003", mode=PAGE_CUR_G, prebuilt=0x620000031108, match_mode=0, direction=1) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:4704
#4  0x0000000001d99c8b in ha_innobase::general_fetch (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003", direction=1, match_mode=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9601
#5  0x0000000001d9b380 in ha_innobase::rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9811
#6  0x000000000162522d in handler::ha_rnd_next (this=0x61c0000208a8, buf=0x6190000b22b8 "\375\003") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#7  0x0000000001b927b0 in rr_sequential (info=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#8  0x00000000009e4e36 in READ_RECORD::read_record (this=0x7fffd05ef780) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#9  0x0000000000fb8192 in mysql_update (thd=0x62b0000af208, table_list=0x62b0000b6330, select_lex=0x62b0000b3920, values=..., limit=18446744073709551611, ignore=false, found_return=0x7fffd05f1f20, updated_return=0x7fffd05f1f40) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:958
#10 0x0000000000c0d8d5 in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#11 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

7. Locks released

#0  lock_release (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:4294
#1  0x0000000001f8a34e in lock_trx_release_locks (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6325
#2  0x00000000023ecd7e in trx_commit_in_memory (trx=0x7fffe9772a38, mtr=0x7fffd05ee560) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1338
#3  0x00000000023eaf44 in trx_commit_low (trx=0x7fffe9772a38, mtr=0x7fffd05ee560) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1552
#4  0x00000000023eeee4 in trx_commit (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1576
#5  0x00000000023f1756 in trx_commit_for_mysql (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/trx/trx0trx.cc:1722
#6  0x0000000001d7723b in innobase_commit_low (trx=0x7fffe9772a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:4416
#7  0x0000000001dd952e in innobase_commit_ordered_2 (trx=0x7fffe9772a38, thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:4538
#8  0x0000000001ddb854 in innobase_commit_ordered (hton=0x614000002048, thd=0x62b0000af208, all=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:4598
#9  0x00000000019e670b in TC_LOG::run_commit_ordered (this=0x52b0be0 <mysql_bin_log>, thd=0x62b0000af208, all=false) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:8949
#10 0x00000000019e5e68 in MYSQL_BIN_LOG::trx_group_commit_leader (this=0x52b0be0 <mysql_bin_log>, leader=0x7fffd05efd20) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:8183
#11 0x00000000019df696 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x52b0be0 <mysql_bin_log>, entry=0x7fffd05efd20) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7772
#12 0x00000000019df44d in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x52b0be0 <mysql_bin_log>, thd=0x62b0000af208, cache_mngr=0x61b000023088, end_ev=0x7fffd05f0300, all=false, using_stmt_cache=true, using_trx_cache=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7427
#13 0x00000000019fa9f4 in binlog_flush_cache (thd=0x62b0000af208, cache_mngr=0x61b000023088, end_ev=0x7fffd05f0300, all=false, using_stmt=true, using_trx=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1785
#14 0x00000000019f3fee in binlog_commit_flush_xid_caches (thd=0x62b0000af208, cache_mngr=0x61b000023088, all=false, xid=9) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1893
#15 0x00000000019f38da in MYSQL_BIN_LOG::log_and_order (this=0x52b0be0 <mysql_bin_log>, thd=0x62b0000af208, xid=9, all=false, need_prepare_ordered=false, need_commit_ordered=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:9732
#16 0x0000000001619af2 in ha_commit_trans (thd=0x62b0000af208, all=false) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:1623
#17 0x000000000118cc52 in trans_commit_stmt (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/transaction.cc:436
#18 0x0000000000c1cc6f in mysql_execute_command (thd=0x62b0000af208) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6139
#19 0x0000000000bf7415 in mysql_parse (thd=0x62b0000af208, rawbuf=0x62b0000b6228 "update n1 set x= x + 1", length=22, parser_state=0x7fffd05f6f60, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

Info

/* Basic lock modes */
enum lock_mode {
    LOCK_IS = 0,    /* intention shared */
    LOCK_IX,    /* intention exclusive */
    LOCK_S,     /* shared */
    LOCK_X,     /* exclusive */
    LOCK_AUTO_INC,  /* locks the auto-inc counter of a table
            in an exclusive mode */
    LOCK_NONE,  /* this is used elsewhere to note consistent read */
    LOCK_NUM = LOCK_NONE, /* number of lock modes */
    LOCK_NONE_UNSET = 255
};

Calls of interest

lock_table()

midenok commented 5 years ago

Info: debug IB

rec_printer() example

    DBUG_LOG("ib_cur",
         "insert " << index->name << " (" << index->id << ") by "
         << ib::hex(thr ? thr->graph->trx->id : 0)
         << ' ' << rec_printer(entry).str());

Locks instrumentation

/** Print the record lock into the given output stream
@param[in,out]  out the output stream
@return the given output stream. */
inline
std::ostream& lock_rec_t::print(std::ostream& out) const
{
    out << "[lock_rec_t: space=" << space << ", page_no=" << page_no
        << ", n_bits=" << n_bits << "]";
    return(out);
}

/** Print the table lock into the given output stream
@param[in,out]  out the output stream
@return the given output stream. */
inline
std::ostream& lock_table_t::print(std::ostream& out) const
{
    out << "[lock_table_t: name=" << table->name << "]";
    return(out);
}

midenok commented 5 years ago

Bad

1. Deadlock detected

#0  0x0000000000f03e06 in DeadlockChecker::search (this=0x7ffff06a9ef0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6901
#1  0x0000000000ef3fa1 in DeadlockChecker::check_and_resolve (lock=0x7ffff11ae4c8, trx=0x7ffff11ae248) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:7041
#2  0x0000000000ef352a in lock_rec_enqueue_waiting (type_mode=2563, block=0x7ffff099d138, heap_no=2, index=0x7fff9c02ff08, thr=0x7fffa0026070, prdt=0x0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1738
#3  0x0000000000efc967 in lock_rec_insert_check_and_lock (flags=0, rec=0x7ffff0aec063 "infimum", block=0x7ffff099d138, index=0x7fff9c02ff08, thr=0x7fffa0026070, mtr=0x7ffff06ab520, inherit=0x7ffff06aaefd) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5349
#4  0x0000000001127480 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7ffff06aba30, entry=0x7fffa0019ff8, thr=0x7fffa0026070, mtr=0x7ffff06ab520, inherit=0x7ffff06aaefd) at /home/midenok/src/mariadb/trunk/src/storage/innobase/btr/btr0cur.cc:3247
#5  0x0000000001125e4a in btr_cur_optimistic_insert (flags=0, cursor=0x7ffff06aba30, offsets=0x7ffff06ab1e8, heap=0x7ffff06ab510, entry=0x7fffa0019ff8, rec=0x7ffff06ab180, big_rec=0x7ffff06aba18, n_ext=0, thr=0x7fffa0026070, mtr=0x7ffff06ab520) at /home/midenok/src/mariadb/trunk/src/storage/innobase/btr/btr0cur.cc:3483
#6  0x0000000000fcd2f6 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x7fff9c02ff08, n_uniq=2, entry=0x7fffa0019ff8, n_ext=0, thr=0x7fffa0026070, dup_chk_only=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:2747
#7  0x0000000000fd1bc4 in row_ins_clust_index_entry (index=0x7fff9c02ff08, entry=0x7fffa0019ff8, thr=0x7fffa0026070, n_ext=0, dup_chk_only=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3271
#8  0x0000000000fd9dfc in row_ins_index_entry (index=0x7fff9c02ff08, entry=0x7fffa0019ff8, thr=0x7fffa0026070) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3398
#9  0x0000000000fd918f in row_ins_index_entry_step (node=0x7fffa0025da0, thr=0x7fffa0026070) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3567
#10 0x0000000000fd2d34 in row_ins (node=0x7fffa0025da0, thr=0x7fffa0026070) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3710
#11 0x0000000000fd28ee in row_ins_step (thr=0x7fffa0026070) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3955
#12 0x0000000000ffc228 in row_insert_for_mysql (mysql_rec=0x7fffa001d200 "\375\002", prebuilt=0x7fffa0025148, ins_mode=ROW_INS_NORMAL) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:1459
#13 0x0000000000e4127d in ha_innobase::write_row (this=0x7fffa0008c90, record=0x7fffa001d200 "\375\002") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:8078
#14 0x0000000000bc38e7 in handler::ha_write_row (this=0x7fffa0008c90, buf=0x7fffa001d200 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#15 0x0000000001493e54 in ha_partition::write_row (this=0x7fffa000a370, buf=0x7fffa001d200 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:4331
#16 0x0000000000bc3888 in handler::ha_write_row (this=0x7fffa000a370, buf=0x7fffa001d200 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#17 0x00000000007ee3f5 in TABLE::vers_insert_history_row (this=0x7fffa001c058) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1680
#18 0x000000000096de5f in mysql_update (thd=0x7fffa0000d28, table_list=0x7fffa0011100, select_lex=0x7fffa0005440, values=..., limit=18446744073709551615, ignore=false, found_return=0x7ffff06af140, updated_return=0x7ffff06af138) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:1061

6898                    if (lock->trx == m_start) {
6899                            /* Found a cycle. */
6900                            notify(lock);
6901                            return select_victim();
6902                    }

2. Transaction set victim

#0  VICTIM::VICTIM (this=0x7fffe0e9a300, trx0=0x7fffedac2920, set0=true) at /home/midenok/src/mariadb/trunk/src/storage/innobase/include/lock0types.h:275
#1  0x0000000001f92036 in DeadlockChecker::trx_rollback (this=0x7fffe0e9a480) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6992
#2  0x0000000001f7220f in DeadlockChecker::check_and_resolve (lock=0x7fffedac3cb8, trx=0x7fffedac3a38) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:7062

frame 2

7037            do {
7038                    DeadlockChecker checker(trx, lock, s_lock_mark_counter,
7039                                            report_waiters);
7040
7041                    victim_trx = checker.search();
7042
7043                    /* Search too deep, we rollback the joining transaction only
7044                    if it is possible to rollback. Otherwise we rollback the
7045                    transaction that is holding the lock that the joining
7046                    transaction wants. */
7047                    if (checker.is_too_deep()) {
7048
7049                            ut_ad(trx == checker.m_start);
7050                            ut_ad(trx == victim_trx);
7051
7052                            rollback_print(victim_trx, lock);
7053
7054                            MONITOR_INC(MONITOR_DEADLOCK);
7055
7056                            break;
7057
7058                    } else if (victim_trx != NULL && victim_trx != trx) {
7059
7060                            ut_ad(victim_trx == checker.m_wait_lock->trx);
7061
7062                            checker.trx_rollback();
7063
7064                            lock_deadlock_found = true;
7065
7066                            MONITOR_INC(MONITOR_DEADLOCK);
7067                    }
7068
7069            } while (victim_trx != NULL && victim_trx != trx);

midenok commented 5 years ago

Info: on heap number (13 bits)

https://blog.jcole.us/2013/01/10/the-physical-structure-of-records-in-innodb/

Order: The order in which this record was inserted into the heap. Heap records (which include infimum and supremum) are numbered from 0. Infimum is always order 0, supremum is always order 1. User records inserted will be numbered from 2.

midenok commented 5 years ago

Bad: DeadlockChecker::search() iterations (T2)

T1

#14 0x0000000000f575ed in os_event_wait_low (event=0x7f3ce4035270, reset_sig_count=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/os/os0event.cc:515
#15 0x0000000000f11817 in lock_wait_suspend_thread (thr=0x7f3ce400e510) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0wait.cc:356
#16 0x0000000000ff9ab5 in row_mysql_handle_errors (new_err=0x7f3d480f0c7c, trx=0x7f3d523b8130, thr=0x7f3ce400e510, savept=0x0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:740
#17 0x00000000010449eb in row_search_mvcc (buf=0x7f3ce4039e1a '\245' <repeats 51 times>, "\001", mode=PAGE_CUR_L, prebuilt=0x7f3ce400da08, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5635
#18 0x0000000000e451ae in ha_innobase::index_read (this=0x7f3ce4110150, buf=0x7f3ce4039e1a '\245' <repeats 51 times>, "\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_BEFORE_KEY) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9336
#19 0x0000000000e45e38 in ha_innobase::index_last (this=0x7f3ce4110150, buf=0x7f3ce4039e1a '\245' <repeats 51 times>, "\001") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9733
#20 0x0000000000bb9376 in handler::ha_index_last (this=0x7f3ce4110150, buf=0x7f3ce4039e1a '\245' <repeats 51 times>, "\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:3002
#21 0x000000000149a792 in ha_partition::handle_ordered_index_scan (this=0x7f3ce40f8250, buf=0x7f3ce4013920 "\377", reverse_order=false) at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:7522
#22 0x000000000149b384 in ha_partition::common_first_last (this=0x7f3ce40f8250, buf=0x7f3ce4013920 "\377") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:5750
#23 0x000000000149b403 in ha_partition::index_last (this=0x7f3ce40f8250, buf=0x7f3ce4013920 "\377") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:5725
#24 0x0000000000bb9338 in handler::ha_index_last (this=0x7f3ce40f8250, buf=0x7f3ce4013920 "\377") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:3002
#25 0x00000000007e5819 in mysql_ha_read (thd=0x7f3ce4000cf8, tables=0x7f3ce40141c8, mode=RLAST, keyname=0x7f3ce4014888 "primary", key_expr=0x7f3ce4014df8, ha_rkey_mode=HA_READ_KEY_EXACT, cond=0x0, select_limit_cnt=1, offset_limit_cnt=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_handler.cc:928
#26 0x0000000000844141 in mysql_execute_command (thd=0x7f3ce4000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:5574
#27 0x00000000008373e0 in mysql_parse (thd=0x7f3ce4000cf8, rawbuf=0x7f3ce4014050 "handler h read `primary` prev", length=29, parser_state=0x7f3d480f45e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

T2

#0  DeadlockChecker::search (this=0x7f3d480a2ef0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:6875
#1  0x0000000000ef4041 in DeadlockChecker::check_and_resolve (lock=0x7f3d523b94c8, trx=0x7f3d523b9248) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:7042
#2  0x0000000000ef35ca in lock_rec_enqueue_waiting (type_mode=2563, block=0x7f3d51bb8f48, heap_no=2, index=0x7f3ce402ff08, thr=0x7f3ce8025820, prdt=0x0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1738
#3  0x0000000000efca07 in lock_rec_insert_check_and_lock (flags=0, rec=0x7f3d51c38063 "infimum", block=0x7f3d51bb8f48, index=0x7f3ce402ff08, thr=0x7f3ce8025820, mtr=0x7f3d480a4520, inherit=0x7f3d480a3efd) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5349
#4  0x00000000011279c0 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7f3d480a4a30, entry=0x7f3ce8023fe8, thr=0x7f3ce8025820, mtr=0x7f3d480a4520, inherit=0x7f3d480a3efd) at /home/midenok/src/mariadb/trunk/src/storage/innobase/btr/btr0cur.cc:3247
#5  0x000000000112638a in btr_cur_optimistic_insert (flags=0, cursor=0x7f3d480a4a30, offsets=0x7f3d480a41e8, heap=0x7f3d480a4510, entry=0x7f3ce8023fe8, rec=0x7f3d480a4180, big_rec=0x7f3d480a4a18, n_ext=0, thr=0x7f3ce8025820, mtr=0x7f3d480a4520) at /home/midenok/src/mariadb/trunk/src/storage/innobase/btr/btr0cur.cc:3483
#6  0x0000000000fcd4d6 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x7f3ce402ff08, n_uniq=2, entry=0x7f3ce8023fe8, n_ext=0, thr=0x7f3ce8025820, dup_chk_only=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:2747
#7  0x0000000000fd1da4 in row_ins_clust_index_entry (index=0x7f3ce402ff08, entry=0x7f3ce8023fe8, thr=0x7f3ce8025820, n_ext=0, dup_chk_only=false) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3271
#8  0x0000000000fd9fdc in row_ins_index_entry (index=0x7f3ce402ff08, entry=0x7f3ce8023fe8, thr=0x7f3ce8025820) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3398
#9  0x0000000000fd936f in row_ins_index_entry_step (node=0x7f3ce8025550, thr=0x7f3ce8025820) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3567
#10 0x0000000000fd2f14 in row_ins (node=0x7f3ce8025550, thr=0x7f3ce8025820) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3710
#11 0x0000000000fd2ace in row_ins_step (thr=0x7f3ce8025820) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0ins.cc:3955
#12 0x0000000000ffc408 in row_insert_for_mysql (mysql_rec=0x7f3ce801a690 "\375\002", prebuilt=0x7f3ce80248f8, ins_mode=ROW_INS_NORMAL) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:1459
#13 0x0000000000e4131d in ha_innobase::write_row (this=0x7f3ce8018d10, record=0x7f3ce801a690 "\375\002") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:8078
#14 0x0000000000bc3987 in handler::ha_write_row (this=0x7f3ce8018d10, buf=0x7f3ce801a690 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#15 0x0000000001494394 in ha_partition::write_row (this=0x7f3ce8026aa0, buf=0x7f3ce801a690 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:4331
#16 0x0000000000bc3928 in handler::ha_write_row (this=0x7f3ce8026aa0, buf=0x7f3ce801a690 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6682
#17 0x00000000007ee495 in TABLE::vers_insert_history_row (this=0x7f3ce801c058) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1680
#18 0x000000000096deff in mysql_update (thd=0x7f3ce8000d28, table_list=0x7f3ce8011100, select_lex=0x7f3ce8005440, values=..., limit=18446744073709551615, ignore=false, found_return=0x7f3d480a8140, updated_return=0x7f3d480a8138) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:1061
#19 0x000000000083f7d6 in mysql_execute_command (thd=0x7f3ce8000d28) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4353
#20 0x00000000008373e0 in mysql_parse (thd=0x7f3ce8000d28, rawbuf=0x7f3ce8011028 "update t1 set c= 4", length=18, parser_state=0x7f3d480a95e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7892

frame 4 (T2: update t1 set c= 4)

(rr) p thr->graph->trx
$11 = (trx_t *) 0x7f3d523b9248

thread 28 frame 17 (T1: handler h read `primary` prev)

(rr) p trx
$12 = (trx_t *) 0x7f3d523b8130

1. T2-II-W vs T2-X: no conflict, getting next lock

(rr) p dbug_print(m_wait_lock)
$3 = 0x7f3ce8027670 "[lock_t: trx=0x7f3d523b9248 (3:1), type_mode=2851=REC|X|WAIT|GAP|INSERT_INTENTION [lock_rec_t: space=143, page_no=3, n_bits=72]]"
(rr) p dbug_print(lock)
$4 = 0x7f3ce8020ec0 "[lock_t: trx=0x7f3d523b9248 (3:1), type_mode=35=REC|X [lock_rec_t: space=143, page_no=3, n_bits=72]]"

6893                    if (!lock_has_to_wait(m_wait_lock, lock)) {
6894                            /* No conflict, next lock */
6895                            lock = get_next_lock(lock, heap_no);
6896                            continue;
6897                    }

2. T2-II-W vs T1-S-W: conflict, pushing state

(rr) p dbug_print(m_wait_lock)
$5 = 0x7f3ce8024660 "[lock_t: trx=0x7f3d523b9248 (3:1), type_mode=2851=REC|X|WAIT|GAP|INSERT_INTENTION [lock_rec_t: space=143, page_no=3, n_bits=72]]"
(rr) p dbug_print(lock)
$6 = 0x7f3ce801ebd0 "[lock_t: trx=0x7f3d523b8130 (3:1), type_mode=290=REC|S|WAIT [lock_rec_t: space=143, page_no=3, n_bits=72]]"

6922                    if (lock->trx->lock.que_state == TRX_QUE_LOCK_WAIT) {
6923                            /* Another trx ahead has requested a lock in an
6924                            incompatible mode, and is itself waiting for a lock. */
6925
6926                            ++m_cost;
6927
6928                            if (!push(lock, heap_no)) {
6929                                    m_too_deep = true;
6930                                    return m_start;
6931                            }
6932
6933                            m_wait_lock = lock->trx->lock.wait_lock;
6934
6935                            lock = get_first_lock(&heap_no);
6936
6937                            if (is_visited(lock)) {
6938                                    lock = get_next_lock(lock, heap_no);
6939                            }
6940                    } else {

(rr) p heap_no
$7 = 2
(rr)  p is_visited(lock)
$21 = false

3. T1-S-W vs T2-X: conflict, found cycle

(rr) p dbug_print(m_wait_lock)
$8 = 0x7f3ce801ebd0 "[lock_t: trx=0x7f3d523b8130 (3:1), type_mode=290=REC|S|WAIT [lock_rec_t: space=143, page_no=3, n_bits=72]]"
(rr) p dbug_print(lock)
$9 = 0x7f3ce8020ec0 "[lock_t: trx=0x7f3d523b9248 (3:1), type_mode=35=REC|X [lock_rec_t: space=143, page_no=3, n_bits=72]]"

6899                    if (lock->trx == m_start) {
6900                            /* Found a cycle. */
6901                            notify(lock);
6902                            return select_victim();
6903                    }

midenok commented 5 years ago

Good

There is no good stack traces for such conflict resolution. I.e. DeadlockChecker::search() was never called from TABLE::vers_insert_history_row().

Cause

No real deadlock, but incomplete conflict detection:

T1-S-W waits on T2-X lock;
T2-II-W has to wait T1-S-W and here conflict resolution starts;
Conflict resolution goes through a chain of locks: a. (T2-II-W, T2-X): ok b. (T2-II-W, T1-S-W): conflict, traversing from T1-S-W c. (T1-S-W, T2-X): conflict, found cycle (because resolution started from T2).

The weak point here is 2. (lock_rec_has_to_wait()), because T2-II-W doesn't have to wait T1: T2 already got X next-key lock that also holds the gap before the record.

midenok commented 5 years ago

T2-X is next-key lock, which means it also holds a gap before record. T2-II-W is gap lock, which means it holds only a gap before record. If we already X-locked a gap, then we don't need to wait to lock that gap again.

Calls of interest

lock_rec_other_has_expl_req()
lock_rec_has_expl()
lock_rec_has_to_wait()
lock_rec_other_has_conflicting()

Fix

Allow lock in lock_rec_other_has_conflicting() if there is already non-waiting stronger or equal lock in this transaction (lock_rec_has_expl()).

midenok commented 5 years ago

Bug 1: `innodb.auto_increment_dup,log-bin` fails

Result

mysqltest: At line 89: query 'INSERT INTO t1(k) VALUES (2), (4), (5) ON DUPLICATE KEY UPDATE c='2'' succeeded - should have failed with errno 1205...

Reproduce

--source include/have_innodb.inc
--source include/have_debug.inc
--source include/have_debug_sync.inc
--source include/innodb_binlog.inc

create or replace table t1(id int not null auto_increment primary key, k int,
  c char(1), unique key(k)) engine innodb;

--connect(con2, localhost, root)
--send set debug_sync='now wait_for write_row_done'
--connect(con1, localhost, root)
set debug_sync='ha_write_row_end signal write_row_done wait_for continue';
--send insert into t1(k) values (1), (2), (3) on duplicate key update c='1'
--connection con2
--reap

set debug_sync='execute_command_after_close_tables signal continue';
--error ER_LOCK_WAIT_TIMEOUT
insert into t1(k) values (2), (4), (5) on duplicate key update c='2';

drop table t1;

set debug_sync='reset';
--disconnect con1
--disconnect con2
--connection default

Cause

From log:

lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d4c8) [lock_t: trx=0x7fc6c4f3d248 (6:4), type_mode=35=REC|X [lock_rec_t: space=0, page_no=307, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d370) [lock_t: trx=0x7fc6c4f3d248 (7:4), type_mode=35=REC|X [lock_rec_t: space=0, page_no=308, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (2:1), type_mode=35=REC|X [lock_rec_t: space=5, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (3:1), type_mode=35=REC|X [lock_rec_t: space=5, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (3:1), type_mode=35=REC|X [lock_rec_t: space=5, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (3:1), type_mode=35=REC|X [lock_rec_t: space=5, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (4:1), type_mode=35=REC|X [lock_rec_t: space=5, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d4c8) [lock_t: trx=0x7fc6c4f3d248 (6:4), type_mode=35=REC|X [lock_rec_t: space=0, page_no=307, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d370) [lock_t: trx=0x7fc6c4f3d248 (7:4), type_mode=35=REC|X [lock_rec_t: space=0, page_no=308, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (2:1), type_mode=35=REC|X [lock_rec_t: space=6, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (3:1), type_mode=35=REC|X [lock_rec_t: space=6, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (3:1), type_mode=35=REC|X [lock_rec_t: space=6, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (2:1), type_mode=547=REC|X|GAP [lock_rec_t: space=6, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3c130, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3c258) [lock_t: trx=0x7fc6c4f3c130 (4:1), type_mode=547=REC|X|GAP [lock_rec_t: space=6, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d4c8) [lock_t: trx=0x7fc6c4f3d248 (6:4), type_mode=35=REC|X [lock_rec_t: space=0, page_no=307, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d370) [lock_t: trx=0x7fc6c4f3d248 (7:4), type_mode=35=REC|X [lock_rec_t: space=0, page_no=308, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d370) [lock_t: trx=0x7fc6c4f3d248 (2:1), type_mode=35=REC|X [lock_rec_t: space=7, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3e360, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3e488) [lock_t: trx=0x7fc6c4f3e360 (2:1), type_mode=35=REC|X [lock_rec_t: space=7, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3e360, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3e488) [lock_t: trx=0x7fc6c4f3e360 (3:1), type_mode=35=REC|X [lock_rec_t: space=7, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3e360, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3e488) [lock_t: trx=0x7fc6c4f3e360 (3:1), type_mode=35=REC|X [lock_rec_t: space=7, page_no=4, n_bits=72]]
lock_rec_other_has_conflicting: ib_lock: NO_CONFLICTS(trx=0x7fc6c4f3d248, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7fc6c4f3d4c8) [lock_t: trx=0x7fc6c4f3d248 (4:1), type_mode=547=REC|X|GAP [lock_rec_t: space=7, page_no=4, n_bits=72]]

Not a bug, because this is result of optimization (bogus deadlock).

midenok commented 5 years ago

Bug 2: `versioning.update` fails

Result

mysqltest: At line 174: query 'update t1 set a = 'bar'' succeeded - should have failed with errno 1213...

Reproduce

source suite/versioning/engines.inc;
source suite/versioning/common.inc;
create or replace table t1 (pk int, a char(3), b char(3), primary key(pk))
with system versioning engine=innodb;

insert into t1 (pk) values (1);
connect (con1,localhost,root,,test);
start transaction;
select * from t1 for update;
connection default;
send update t1 set b = 'foo';
connection con1;
let $wait_condition= select count(*) from information_schema.innodb_lock_waits;
source include/wait_condition.inc;
error ER_LOCK_DEADLOCK;
update t1 set a = 'bar';
disconnect con1;
connection default;
reap;
drop table t1;
source suite/versioning/common_finish.inc;

Cause

Deadlock does not occur in upstream without system versioning. Not a bug, as this deadlock is direct implication of MDEV-18706.

TODO

[x] Remove BIT logging
[x] Test case
[x] + && (!is_insert_intention() // FIXME: test
[ ] All logging via classes?

midenok commented 5 years ago

Bug 3: SELECT FOR UPDATE doesn't display inserted record

Reproduce

--source include/have_innodb.inc
create or replace table t1 (pk int primary key, x int) engine innodb;
insert into t1 values (2, 1);
start transaction;
update t1 set x= x + 1;
connect (con1,localhost,root,,test);
send select * from t1 for update;
connection default;
--let $wait_condition= select count(*) from information_schema.innodb_lock_waits
--source include/wait_condition.inc
insert into t1 values (1, 1);
commit;
connection con1;
--echo # No ER_LOCK_DEADLOCK here:
reap;
connection default;
disconnect con1;
drop table t1;

Result

# No ER_LOCK_DEADLOCK here:
pk      x
2       2

Expected

# No ER_LOCK_DEADLOCK here:
pk      x
1       1
2       2

Good

Reverse order works fine:

select * from t1 order by pk desc for update;

midenok commented 5 years ago

1. SELECT locks the record

#0  lock_rec_lock (impl=false, mode=3, block=0x7fffdc048f08, heap_no=2, index=0x36d1518, thr=0x7fff840c0c60) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:1930
#1  0x0000000000f005c9 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffdc048f08, rec=0x7fffdcc3807e "\200", index=0x36d1518, offsets=0x7ffff478fcf0, mode=LOCK_X, gap_mode=0, thr=0x7fff840c0c60) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0lock.cc:5846
#2  0x0000000001046927 in sel_set_rec_lock (pcur=0x7fff840c03f8, rec=0x7fffdcc3807e "\200", index=0x36d1518, offsets=0x7ffff478fcf0, mode=3, type=0, thr=0x7fff840c0c60, mtr=0x7ffff4790018) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:1262
#3  0x00000000010422bc in row_search_mvcc (buf=0x7fff840d4028 "\377", mode=PAGE_CUR_G, prebuilt=0x7fff840c0228, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5014
#4  0x0000000000e45d5e in ha_innobase::index_read (this=0x7fff840b5600, buf=0x7fff840d4028 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9321
#5  0x0000000000e46908 in ha_innobase::index_first (this=0x7fff840b5600, buf=0x7fff840d4028 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9695
#6  0x0000000000e46b7a in ha_innobase::rnd_next (this=0x7fff840b5600, buf=0x7fff840d4028 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9788
#7  0x0000000000bb8286 in handler::ha_rnd_next (this=0x7fff840b5600, buf=0x7fff840d4028 "\377") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#8  0x0000000000d99dd3 in rr_sequential (info=0x7fff78013a98) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#9  0x000000000077babb in READ_RECORD::read_record (this=0x7fff78013a98) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#10 0x00000000008afff0 in join_init_read_record (tab=0x7fff780139d0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:21141
#11 0x00000000008cd628 in sub_select (join=0x7fff78012520, join_tab=0x7fff780139d0, end_of_records=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:20197
#12 0x00000000008b4109 in do_select (join=0x7fff78012520, procedure=0x0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:19738
#13 0x00000000008b2e55 in JOIN::exec_inner (this=0x7fff78012520) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:4457
#14 0x00000000008b1c9e in JOIN::exec (this=0x7fff78012520) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:4239
#15 0x0000000000886cf8 in mysql_select (thd=0x7fff78000cf8, tables=0x7fff78011518, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fff780124f8, unit=0x7fff78004c20, select_lex=0x7fff78010f50) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:4671
#16 0x00000000008863a1 in handle_select (thd=0x7fff78000cf8, lex=0x7fff78004b58, result=0x7fff780124f8, setup_tables_done_option=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:413
#17 0x0000000000848010 in execute_sqlcom_select (thd=0x7fff78000cf8, all_tables=0x7fff78011518) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6356
#18 0x000000000083df4e in mysql_execute_command (thd=0x7fff78000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:3898
#19 0x0000000000837450 in mysql_parse (thd=0x7fff78000cf8, rawbuf=0x7fff78010eb0 "select * from t1 for update", length=27, parser_state=0x7ffff4794640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7908

frame 1

(gdb) p gap_mode
$6 = 0

Gap mode is LOCK_ORDINARY.

2. SELECT waits for X lock

#6  0x0000000000f112fc in lock_wait_suspend_thread (thr=0x7fff840c0c60) at /home/midenok/src/mariadb/trunk/src/storage/innobase/lock/lock0wait.cc:347
#7  0x0000000000ff9475 in row_mysql_handle_errors (new_err=0x7ffff479054c, trx=0x7ffff4881360, thr=0x7fff840c0c60, savept=0x0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0mysql.cc:740
#8  0x00000000010442ab in row_search_mvcc (buf=0x7fff840d4028 "\377", mode=PAGE_CUR_G, prebuilt=0x7fff840c0228, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk/src/storage/innobase/row/row0sel.cc:5635
#9  0x0000000000e45d5e in ha_innobase::index_read (this=0x7fff840b5600, buf=0x7fff840d4028 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9321
#10 0x0000000000e46908 in ha_innobase::index_first (this=0x7fff840b5600, buf=0x7fff840d4028 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9695
#11 0x0000000000e46b7a in ha_innobase::rnd_next (this=0x7fff840b5600, buf=0x7fff840d4028 "\377") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:9788
#12 0x0000000000bb8286 in handler::ha_rnd_next (this=0x7fff840b5600, buf=0x7fff840d4028 "\377") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:2834
#13 0x0000000000d99dd3 in rr_sequential (info=0x7fff78013a98) at /home/midenok/src/mariadb/trunk/src/sql/records.cc:477
#14 0x000000000077babb in READ_RECORD::read_record (this=0x7fff78013a98) at /home/midenok/src/mariadb/trunk/src/sql/records.h:69
#15 0x00000000008afff0 in join_init_read_record (tab=0x7fff780139d0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:21141
#16 0x00000000008cd628 in sub_select (join=0x7fff78012520, join_tab=0x7fff780139d0, end_of_records=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:20197
#17 0x00000000008b4109 in do_select (join=0x7fff78012520, procedure=0x0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:19738
#18 0x00000000008b2e55 in JOIN::exec_inner (this=0x7fff78012520) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:4457
#19 0x00000000008b1c9e in JOIN::exec (this=0x7fff78012520) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:4239
#20 0x0000000000886cf8 in mysql_select (thd=0x7fff78000cf8, tables=0x7fff78011518, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fff780124f8, unit=0x7fff78004c20, select_lex=0x7fff78010f50) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:4671
#21 0x00000000008863a1 in handle_select (thd=0x7fff78000cf8, lex=0x7fff78004b58, result=0x7fff780124f8, setup_tables_done_option=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:413
#22 0x0000000000848010 in execute_sqlcom_select (thd=0x7fff78000cf8, all_tables=0x7fff78011518) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6356
#23 0x000000000083df4e in mysql_execute_command (thd=0x7fff78000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:3898
#24 0x0000000000837450 in mysql_parse (thd=0x7fff78000cf8, rawbuf=0x7fff78010eb0 "select * from t1 for update", length=27, parser_state=0x7ffff4794640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:7908

midenok commented 5 years ago

Good 2

T1

create or replace table t1 (pk int primary key, x int) engine innodb;
insert into t1 values (1, 1);
insert into t1 values (3, 1);
start transaction;
update t1 set x= x + 1;

T2

select * from t1 for update;

T1

insert into t1 values (2, 1); commit;

Cause

When pcur was positioned on infimum, it restores to the first record at the point of position store:

/**************************************************************//**
Restores the stored position of a persistent cursor bufferfixing the page and
obtaining the specified latches. If the cursor position was saved when the
(1) cursor was positioned on a user record: this function restores the position
to the last record LESS OR EQUAL to the stored record;
(2) cursor was positioned on a page infimum record: restores the position to
the last record LESS than the user record which was the successor of the page
infimum;
(3) cursor was positioned on the page supremum: restores to the first record
GREATER than the user record which was the predecessor of the supremum.
(4) cursor was positioned before the first or after the last in an empty tree:
restores to before first or after the last in the tree.
@return TRUE if the cursor position was stored when it was on a user
record and it can be restored on a user record whose ordering fields
are identical to the ones of the original user record */
ibool
btr_pcur_restore_position_func(
...

As test shows, (2) is already wrong, because it restores on user record (probably this is optimistic restoration).

Expected

for (2)

In case moves_up == true:

(2) cursor was positioned on a page infimum record: restores the position to
the first successor of the page infimum;

otherwise current behavior is ok.

for (3)

In case moves_up == false:

(3) cursor was positioned on the page supremum: restores the position to
the first predecessor of the supremum.

otherwise current behavior is ok.

midenok commented 5 years ago

Position is stored

#0  btr_pcur_store_position (cursor=0x7fff880d32f8, mtr=0x7ffff47c2018) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/btr/btr0pcur.cc:114
#1  0x0000000001046495 in row_search_mvcc (buf=0x7fff880c2078 "\377", mode=PAGE_CUR_G, prebuilt=0x7fff880d3128, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0sel.cc:5617

frame 1

5606    lock_wait_or_error:
5607            /* Reset the old and new "did semi-consistent read" flags. */
5608            if (UNIV_UNLIKELY(prebuilt->row_read_type
5609                              == ROW_READ_DID_SEMI_CONSISTENT)) {
5610                    prebuilt->row_read_type = ROW_READ_TRY_SEMI_CONSISTENT;
5611            }
5612            did_semi_consistent_read = FALSE;
5613
5614            /*-------------------------------------------------------------*/
5615            if (!dict_index_is_spatial(index)) {
5616                    if (rec) {
5617                            btr_pcur_store_position(pcur, &mtr);
5618                    }
5619            }

(gdb) x/20bx rec
0x7fffdccb007e: 0x80    0x00    0x00    0x01    0x00    0x00    0x00    0x00
0x7fffdccb0086: 0x13    0xdb    0x44    0x00    0x00    0x01    0x65    0x13
0x7fffdccb008e: 0x33    0x80    0x00    0x00

Fix

--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -5614,6 +5614,13 @@ row_search_mvcc(
        /*-------------------------------------------------------------*/
        if (!dict_index_is_spatial(index)) {
                if (rec) {
+                       /* Locked gap may be filled with inserted records.
+                       Make sure we don't miss them. */
+                       if (moves_up) {
+                               btr_pcur_move_to_prev(pcur, &mtr);
+                       } else {
+                               btr_pcur_move_to_next(pcur, &mtr);
+                       }
                        btr_pcur_store_position(pcur, &mtr);
                }
        }
@@ -5650,6 +5657,11 @@ row_search_mvcc(
                        sel_restore_position_for_mysql(
                                &same_user_rec, BTR_SEARCH_LEAF, pcur,
                                moves_up, &mtr);
+                       if (!moves_up) {
+                               btr_pcur_move_to_prev(pcur, &mtr);
+                       } else {
+                               btr_pcur_move_to_next(pcur, &mtr);
+                       }
                }

                if ((srv_locks_unsafe_for_binlog

midenok commented 5 years ago

Bug 4: deadlock on implicit locking

Reproduce

--source include/have_innodb.inc

create or replace table t1 (pk int primary key, x int) engine innodb;
start transaction;
insert into t1 values (3, 1);
connect (con1,localhost,root,,test);
send select * from t1 for update;
connection default;
--let $wait_condition= select count(*) from information_schema.innodb_lock_waits
--source include/wait_condition.inc
insert into t1 values (1, 1);
commit;
connection con1;
--error ER_LOCK_DEADLOCK
reap;
connection default;
show engine innodb status;
disconnect con1;
drop table t1;

1. Explicit lock skipped

#0  lock_rec_insert_check_and_lock (flags=0, rec=0x7fffdcc34063 "infimum", block=0x7fffdc048ca0, index=0x36d2bd8, thr=0x7fff800c2938, mtr=0x7ffff47f3b60, inherit=0x7ffff47f353d) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:5310
#1  0x00000000011293e0 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7ffff47f4070, entry=0x7fff800bce38, thr=0x7fff800c2938, mtr=0x7ffff47f3b60, inherit=0x7ffff47f353d) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/btr/btr0cur.cc:3247
#2  0x0000000001127daa in btr_cur_optimistic_insert (flags=0, cursor=0x7ffff47f4070, offsets=0x7ffff47f3828, heap=0x7ffff47f3b50, entry=0x7fff800bce38, rec=0x7ffff47f37c0, big_rec=0x7ffff47f4058, n_ext=0, thr=0x7fff800c2938, mtr=0x7ffff47f3b60) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/btr/btr0cur.cc:3483
#3  0x0000000000fcf126 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x36d2bd8, n_uniq=1, entry=0x7fff800bce38, n_ext=0, thr=0x7fff800c2938, dup_chk_only=false) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0ins.cc:2752
#4  0x0000000000fd39f4 in row_ins_clust_index_entry (index=0x36d2bd8, entry=0x7fff800bce38, thr=0x7fff800c2938, n_ext=0, dup_chk_only=false) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0ins.cc:3276
#5  0x0000000000fdbc2c in row_ins_index_entry (index=0x36d2bd8, entry=0x7fff800bce38, thr=0x7fff800c2938) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0ins.cc:3403
#6  0x0000000000fdafbf in row_ins_index_entry_step (node=0x7fff800c26c0, thr=0x7fff800c2938) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0ins.cc:3572
#7  0x0000000000fd4b64 in row_ins (node=0x7fff800c26c0, thr=0x7fff800c2938) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0ins.cc:3715
#8  0x0000000000fd471e in row_ins_step (thr=0x7fff800c2938) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0ins.cc:3960
#9  0x0000000000ffdfe8 in row_insert_for_mysql (mysql_rec=0x7fff8004c478 "\375\003", prebuilt=0x7fff800c2168, ins_mode=ROW_INS_NORMAL) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0mysql.cc:1459
#10 0x0000000000e41f3d in ha_innobase::write_row (this=0x7fff800bbae0, record=0x7fff8004c478 "\375\003") at /home/midenok/src/mariadb/trunk2/src/storage/innobase/handler/ha_innodb.cc:8063
#11 0x0000000000bc42a7 in handler::ha_write_row (this=0x7fff800bbae0, buf=0x7fff8004c478 "\375\003") at /home/midenok/src/mariadb/trunk2/src/sql/handler.cc:6682
#12 0x00000000007ecdd7 in write_record (thd=0x7fff80000cf8, table=0x7fff800c0518, info=0x7ffff47f5670) at /home/midenok/src/mariadb/trunk2/src/sql/sql_insert.cc:2053
#13 0x00000000007e935d in mysql_insert (thd=0x7fff80000cf8, table_list=0x7fff80014078, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/midenok/src/mariadb/trunk2/src/sql/sql_insert.cc:1075
#14 0x000000000083ffee in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk2/src/sql/sql_parse.cc:4525
#15 0x00000000008374a0 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80013f90 "insert into t1 values (3, 1)", length=28, parser_state=0x7ffff47f8640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk2/src/sql/sql_parse.cc:7908

5294            lock = lock_rec_get_first(lock_sys.rec_hash, block, heap_no);
5295
5296            if (lock == NULL) {
5297                    /* We optimize CPU time usage in the simplest case */
5298
5299                    lock_mutex_exit();
5300
5301                    if (inherit_in && !dict_index_is_clust(index)) {
5302                            /* Update the page max trx id field */
5303                            page_update_max_trx_id(block,
5304                                                   buf_block_get_page_zip(block),
5305                                                   trx->id, mtr);
5306                    }
5307
5308                    *inherit = false;
5309
5310                    return(DB_SUCCESS);
5311            }
5312
....
5320
5321            /* If another transaction has an explicit lock request which locks
5322            the gap, waiting or granted, on the successor, the insert has to wait.
5323
5324            An exception is the case where the lock by the another transaction
5325            is a gap type lock which it placed to wait for its turn to insert. We
5326            do not consider that kind of a lock conflicting with our insert. This
5327            eliminates an unnecessary deadlock which resulted when 2 transactions
5328            had to wait for their insert. Both had waiting gap type lock requests
5329            on the successor, which produced an unnecessary deadlock. */
5330
5331            const ulint     type_mode = LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION;

2. Implicit lock converted to explicit

#0  lock_rec_create_low (type_mode=1059, space=612, page_no=3, page=0x7fffdcc24000 "\373\004\371D", heap_no=2, index=0x7fff80020e18, trx=0x7ffff4880248, holds_trx_mutex=false) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:1415
#1  0x0000000000ef4ff2 in lock_rec_create (type_mode=1059, block=0x7fffdc048300, heap_no=2, index=0x7fff80020e18, trx=0x7ffff4880248, caller_owns_trx_mutex=false) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/include/lock0lock.ic:126
#2  0x0000000000ef6fa7 in lock_rec_add_to_queue (type_mode=1059, block=0x7fffdc048300, heap_no=2, index=0x7fff80020e18, trx=0x7ffff4880248, caller_owns_trx_mutex=false) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:1901
#3  0x0000000000f0b055 in lock_rec_convert_impl_to_expl_for_trx (block=0x7fffdc048300, rec=0x7fffdcc2407e "\200", index=0x7fff80020e18, trx=0x7ffff4880248, heap_no=2) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:5427
#4  0x0000000000eff9aa in lock_rec_convert_impl_to_expl (caller_trx=0x7ffff4881360, block=0x7fffdc048300, rec=0x7fffdcc2407e "\200", index=0x7fff80020e18, offsets=0x7ffff47c1cf0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:5587
#5  0x0000000000f00f25 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffdc048300, rec=0x7fffdcc2407e "\200", index=0x7fff80020e18, offsets=0x7ffff47c1cf0, mode=LOCK_X, gap_mode=0, thr=0x7fff800bffc0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:5850
#6  0x0000000001048bf7 in sel_set_rec_lock (pcur=0x7fff800bf758, rec=0x7fffdcc2407e "\200", index=0x7fff80020e18, offsets=0x7ffff47c1cf0, mode=3, type=0, thr=0x7fff800bffc0, mtr=0x7ffff47c2018) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0sel.cc:1262
#7  0x00000000010444ec in row_search_mvcc (buf=0x7fff8004c478 "\377", mode=PAGE_CUR_G, prebuilt=0x7fff800bf588, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0sel.cc:5014
#8  0x0000000000e45dae in ha_innobase::index_read (this=0x7fff800b7320, buf=0x7fff8004c478 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/handler/ha_innodb.cc:9321
#9  0x0000000000e46958 in ha_innobase::index_first (this=0x7fff800b7320, buf=0x7fff8004c478 "\377") at /home/midenok/src/mariadb/trunk2/src/storage/innobase/handler/ha_innodb.cc:9695
#10 0x0000000000e46bca in ha_innobase::rnd_next (this=0x7fff800b7320, buf=0x7fff8004c478 "\377") at /home/midenok/src/mariadb/trunk2/src/storage/innobase/handler/ha_innodb.cc:9788
#11 0x0000000000bb82d6 in handler::ha_rnd_next (this=0x7fff800b7320, buf=0x7fff8004c478 "\377") at /home/midenok/src/mariadb/trunk2/src/sql/handler.cc:2834
#12 0x0000000000d99e23 in rr_sequential (info=0x7fff84013a08) at /home/midenok/src/mariadb/trunk2/src/sql/records.cc:477
#13 0x000000000077bb0b in READ_RECORD::read_record (this=0x7fff84013a08) at /home/midenok/src/mariadb/trunk2/src/sql/records.h:69
#14 0x00000000008b0040 in join_init_read_record (tab=0x7fff84013940) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:21141
#15 0x00000000008cd678 in sub_select (join=0x7fff84012490, join_tab=0x7fff84013940, end_of_records=false) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:20197
#16 0x00000000008b4159 in do_select (join=0x7fff84012490, procedure=0x0) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:19738
#17 0x00000000008b2ea5 in JOIN::exec_inner (this=0x7fff84012490) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:4457
#18 0x00000000008b1cee in JOIN::exec (this=0x7fff84012490) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:4239
#19 0x0000000000886d48 in mysql_select (thd=0x7fff84000cf8, tables=0x7fff84011488, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fff84012468, unit=0x7fff84004c20, select_lex=0x7fff84010ec0) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:4671
#20 0x00000000008863f1 in handle_select (thd=0x7fff84000cf8, lex=0x7fff84004b58, result=0x7fff84012468, setup_tables_done_option=0) at /home/midenok/src/mariadb/trunk2/src/sql/sql_select.cc:413
#21 0x0000000000848060 in execute_sqlcom_select (thd=0x7fff84000cf8, all_tables=0x7fff84011488) at /home/midenok/src/mariadb/trunk2/src/sql/sql_parse.cc:6356
#22 0x000000000083df9e in mysql_execute_command (thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk2/src/sql/sql_parse.cc:3898
#23 0x00000000008374a0 in mysql_parse (thd=0x7fff84000cf8, rawbuf=0x7fff84010e20 "select * from t1 for update", length=27, parser_state=0x7ffff47c6640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk2/src/sql/sql_parse.cc:7908

frame 3

5418            if (!trx_state_eq(trx, TRX_STATE_COMMITTED_IN_MEMORY)
5419                && !lock_rec_has_expl(LOCK_X | LOCK_REC_NOT_GAP,
5420                                      block, heap_no, trx)) {
5421
5422                    ulint   type_mode;
5423
5424                    type_mode = (LOCK_REC | LOCK_X | LOCK_REC_NOT_GAP);
5425
5426                    DBUG_LOG("ib_lock", "IMPL_TO_EXPL(trx=" << trx << ")");
5427                    lock_rec_add_to_queue(
5428                            type_mode, block, heap_no, index, trx, FALSE);
5429            }

3. SELECT FOR UPDATE locks record

#0  lock_rec_create_low (type_mode=259, space=612, page_no=3, page=0x7fffdcc24000 "\373\004\371D", heap_no=2, index=0x7fff80020e18, trx=0x7ffff4881360, holds_trx_mutex=true) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:1415
#1  0x0000000000ef4ff2 in lock_rec_create (type_mode=259, block=0x7fffdc048300, heap_no=2, index=0x7fff80020e18, trx=0x7ffff4881360, caller_owns_trx_mutex=true) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/include/lock0lock.ic:126
#2  0x0000000000ef4824 in lock_rec_enqueue_waiting (type_mode=3, block=0x7fffdc048300, heap_no=2, index=0x7fff80020e18, thr=0x7fff800bffc0, prdt=0x0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:1720
#3  0x0000000000efff28 in lock_rec_lock (impl=false, mode=3, block=0x7fffdc048300, heap_no=2, index=0x7fff80020e18, thr=0x7fff800bffc0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:1972
#4  0x0000000000f00f69 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffdc048300, rec=0x7fffdcc2407e "\200", index=0x7fff80020e18, offsets=0x7ffff47c1cf0, mode=LOCK_X, gap_mode=0, thr=0x7fff800bffc0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/lock/lock0lock.cc:5856
#5  0x0000000001048bf7 in sel_set_rec_lock (pcur=0x7fff800bf758, rec=0x7fffdcc2407e "\200", index=0x7fff80020e18, offsets=0x7ffff47c1cf0, mode=3, type=0, thr=0x7fff800bffc0, mtr=0x7ffff47c2018) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0sel.cc:1262
#6  0x00000000010444ec in row_search_mvcc (buf=0x7fff8004c478 "\377", mode=PAGE_CUR_G, prebuilt=0x7fff800bf588, match_mode=0, direction=0) at /home/midenok/src/mariadb/trunk2/src/storage/innobase/row/row0sel.cc:5014

Cause

When implicit lock is converted to explicit it does not lock the gap: LOCK_REC | LOCK_X | LOCK_REC_NOT_GAP. On the other hand explicit insert intention does lock the gap: LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION. Explicit lock is skipped when there is no existing locks for the record.

Fix candidates

Implicit lock converted into insert intention: LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION. I don't see a reason why it is converted into different mode.
When inserting into a gap locked by the same transaction do not create explicit lock. We don't have to wait for locks in same transaction.

midenok commented 5 years ago

Bug 5: rpl_mdev6020,innodb,row fails

Result

Last_Error      Could not execute Delete_rows_v1 event on table test.table10_key_pk_parts_2_int_autoinc; Can't find record in 'table10_key_pk_parts_2_int_autoinc', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log master-bin.000001, end_log_pos 25751

Command

BINLOG '
trxHUxMBAAAAUQAAAFRkAAAAAGsAAAAAAAEABHRlc3QAInRhYmxlMTBfa2V5X3BrX3BhcnRzXzJf
aW50X2F1dG9pbmMABQP+A/4DBP4M/gwe
trxHUxkBAAAAQwAAAJdkAAAAAGsAAAAAAAEABf/+EAAAAO4PAAAAPgAAAPAHAAAACjMyNjM4ODk0
MDgAABUwA2Jwdg==
'/*!*/;
### DELETE FROM `test`.`table10_key_pk_parts_2_int_autoinc`
### WHERE
###   @1=16
###   @2=NULL
###   @3=NULL
###   @4=NULL
###   @5=NULL
### DELETE FROM `test`.`table10_key_pk_parts_2_int_autoinc`
### WHERE
###   @1=15
###   @2=NULL
###   @3=NULL
###   @4=NULL
###   @5=62
### DELETE FROM `test`.`table10_key_pk_parts_2_int_autoinc`
### WHERE
###   @1=7
###   @2='3263889408'
###   @3=806682624
###   @4='bpv'
###   @5=NULL
# Number of rows: 3
# at 25751

table state

MariaDB [test]> select * from table10_key_pk_parts_2_int_autoinc;
+----+-------------+-------------+-----------------+-------------+
| pk | col_char_12 | col_int     | col_char_12_key | col_int_key |
+----+-------------+-------------+-----------------+-------------+
|  1 | r           |        NULL | say             |   459079680 |
|  3 | rgsbpvas    |   462225408 | 1136525312      |           0 |
|  5 | x           |        NULL | you're          |        NULL |
|  7 | 3263889408  |   806682624 | bpv             |        NULL |
|  9 | z           | -1374552064 | pv              |  -134873088 |
| 15 | NULL        |        NULL | NULL            |          62 |
|  2 | 3263889408  |  1806893056 | I'll            |  1410596864 |
|  4 | 3263889408  |        NULL | sbpvasfov       |        NULL |
|  6 | 3263889408  |           6 | on              |        NULL |
|  8 | 3263889408  |        NULL | d               |           8 |
| 10 | vasfovb     |           2 | a               |   586743808 |
| 16 | NULL        |        NULL | NULL            |        NULL |
+----+-------------+-------------+-----------------+-------------+

relay-log.info

5
./slave-relay-bin.000002
25863
master-bin.000001
25563
0
5
./slave-relay-bin.000002
25147
master-bin.000001
24847
0
5
./slave-relay-bin.000002
20974
master-bin.000001
20674
0
5
./slave-relay-bin.000002
20974
master-bin.000001
20674
0

master.info

33
master-bin.000002
343
127.0.0.1
root
...

rpl_mdev6020.log

include/master-slave.inc
[connection master]
connection slave;
include/stop_slave.inc
connection master;
include/rpl_stop_server.inc [server_number=1]
include/rpl_start_server.inc [server_number=1]
connection slave;
SET SQL_LOG_BIN=0;
ALTER TABLE mysql.gtid_slave_pos ENGINE = InnoDB;
SET SQL_LOG_BIN=1;
SET @old_engine= @@GLOBAL.default_storage_engine;
SET GLOBAL default_storage_engine=InnoDB;
SET @old_parallel= @@GLOBAL.slave_parallel_threads;
SET GLOBAL slave_parallel_threads=12;
CHANGE MASTER TO master_host='127.0.0.1', master_port=SERVER_MYPORT_1, master_user='root', master_log_file='master-bi
include/start_slave.inc
connection master;
SET SQL_LOG_BIN=0;
ALTER TABLE mysql.gtid_slave_pos ENGINE = InnoDB;
SET SQL_LOG_BIN=1;
connection slave;

Table DML is here

dml.txt

Slave binlog

binlog ./mysql-test/std_data/mdev6020-mysql-bin.000001

Links

midenok commented 5 years ago

Slave threads positions

1

BINLOG '
trxHUxMBAAAAUQAAAFRkAAAAAGsAAAAAAAEABHRlc3QAInRhYmxlMTBfa2V5X3BrX3BhcnRzXzJf
aW50X2F1dG9pbmMABQP+A/4DBP4M/gwe
trxHUxkBAAAAQwAAAJdkAAAAAGsAAAAAAAEABf/+EAAAAO4PAAAAPgAAAPAHAAAACjMyNjM4ODk0
MDgAABUwA2Jwdg==
'/*!*/;
### DELETE FROM `test`.`table10_key_pk_parts_2_int_autoinc`
### WHERE
###   @1=16
###   @2=NULL
###   @3=NULL
###   @4=NULL
###   @5=NULL
### DELETE FROM `test`.`table10_key_pk_parts_2_int_autoinc`
### WHERE
###   @1=15
###   @2=NULL
###   @3=NULL
###   @4=NULL
###   @5=62
### DELETE FROM `test`.`table10_key_pk_parts_2_int_autoinc`
### WHERE
###   @1=7
###   @2='3263889408'
###   @3=806682624
###   @4='bpv'
###   @5=NULL

2

BINLOG '
trxHUxMBAAAAQgAAAHlhAAAAAGoAAAAAAAEABHRlc3QAE3RhYmxlMTBfaW50X2F1dG9pbmMABf7+
AwMDBP4M/gwb
trxHUxcBAAAAIgAAAJthAAAAAGoAAAAAAAEABf/7FAAAAA==
'/*!*/;
### INSERT INTO `test`.`table10_int_autoinc`
### SET
###   @1=NULL
###   @2=NULL
###   @3=20
###   @4=NULL
###   @5=NULL
# Number of rows: 1
# at 24987

3

BINLOG '
r7xHUxMBAAAAQQAAACtRAAAAAG4AAAAAAAEABHRlc3QAEnRhYmxlMl9pbnRfYXV0b2luYwAF/gP+
AwME/gz+DA8=
r7xHUxcBAAAANwAAAGJRAAAAAG4AAAAAAAEABf/lCAAAAC8AAAAFAAAA5f///38AAAAABgAAAA==
'/*!*/;
### INSERT INTO `test`.`table2_int_autoinc`
### SET
###   @1=NULL
###   @2=8
###   @3=NULL
###   @4=47
###   @5=5
### INSERT INTO `test`.`table2_int_autoinc`
### SET
###   @1=NULL
###   @2=2147483647
###   @3=NULL
###   @4=0
###   @5=6
# Number of rows: 2
# at 20834

4

BINLOG '
r7xHUxMBAAAAQQAAACtRAAAAAG4AAAAAAAEABHRlc3QAEnRhYmxlMl9pbnRfYXV0b2luYwAF/gP+
AwME/gz+DA8=
r7xHUxcBAAAANwAAAGJRAAAAAG4AAAAAAAEABf/lCAAAAC8AAAAFAAAA5f///38AAAAABgAAAA==
'/*!*/;
### INSERT INTO `test`.`table2_int_autoinc`
### SET
###   @1=NULL
###   @2=8
###   @3=NULL
###   @4=47
###   @5=5
### INSERT INTO `test`.`table2_int_autoinc`
### SET
###   @1=NULL
###   @2=2147483647
###   @3=NULL
###   @4=0
###   @5=6
# Number of rows: 2
# at 20834

midenok commented 5 years ago

Info

        if (!moves_up
            && !page_rec_is_supremum(rec)
            && set_also_gap_locks
            && !(srv_locks_unsafe_for_binlog
             || trx->isolation_level <= TRX_ISO_READ_COMMITTED)
            && prebuilt->select_lock_type != LOCK_NONE
            && !dict_index_is_spatial(index)) {

            /* Try to place a gap lock on the next index record
            to prevent phantoms in ORDER BY ... DESC queries */
            const rec_t*    next_rec = page_rec_get_next_const(rec);

            offsets = rec_get_offsets(next_rec, index, offsets,
                          true,
                          ULINT_UNDEFINED, &heap);
            err = sel_set_rec_lock(pcur,
                           next_rec, index, offsets,
                           prebuilt->select_lock_type,
                           LOCK_GAP, thr, &mtr);

            switch (err) {
            case DB_SUCCESS_LOCKED_REC:
                err = DB_SUCCESS;
                /* fall through */
            case DB_SUCCESS:
                break;
            default:
                goto lock_wait_or_error;
            }
        }

        /* If we are doing a 'greater or equal than a primary key
        value' search from a clustered index, and we find a record
        that has that exact primary key value, then there is no need
        to lock the gap before the record, because no insert in the
        gap can be in our search range. That is, no phantom row can
        appear that way.

        An example: if col1 is the primary key, the search is WHERE
        col1 >= 100, and we find a record where col1 = 100, then no
        need to lock the gap before that record. */

        if (index == clust_index
            && mode == PAGE_CUR_GE
            && direction == 0
            && dtuple_get_n_fields_cmp(search_tuple)
            == dict_index_get_n_unique(index)
            && 0 == cmp_dtuple_rec(search_tuple, rec, offsets)) {
no_gap_lock:
            lock_type = LOCK_REC_NOT_GAP;
        }

Fix

--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -5657,10 +5657,12 @@ row_search_mvcc(
                        sel_restore_position_for_mysql(
                                &same_user_rec, BTR_SEARCH_LEAF, pcur,
                                moves_up, &mtr);
-                       if (!moves_up) {
-                               btr_pcur_move_to_prev(pcur, &mtr);
-                       } else {
-                               btr_pcur_move_to_next(pcur, &mtr);
+                       if (same_user_rec) {
+                               if (!moves_up) {
+                                       btr_pcur_move_to_prev(pcur, &mtr);
+                               } else {
+                                       btr_pcur_move_to_next(pcur, &mtr);
+                               }
                        }
                }

TODO

[x] Check row_sel() or document:

It seems that you are only fixing row_search_mvcc() and not its row_sel() counterpart? That might be OK (row_sel() is mostly used for updating system tables, but sometimes also for accessing user tables in FTS). But it should be documented in the commit message.

row_sel() is used only with sel_node_create() which is called by:

row_prebuild_sel_graph()
row_mysql_lock_table()
lock_table_for_trx()
pars_select_list()

row_prebuild_sel_graph() uses it as a dummy query. pars_select_list() is used for internal InnoDB queries. Noted in commit message.

[x] Document the detailed scenario in comments of the test case, and refer to the test case (if needed at all) in the commit message.
[x] Instead of overloading the name T1 (table name or transaction name), I’d suggest to refer to connection names in the test (if named references are needed at all).
[x] Comments in https://github.com/mariadb/server/commit/548b96352a0af2bab7f7d719cf49bae118bc4147
[ ] Fix MDEV-10962?
[x] Answer question:

AFAIU, gap locks can be attached to a delete-marked, committed record. For read-gap-locks (that is, other than insert intention), purge can widen the gap when it removes the anchor record. Question: As a result of purge widening the gap, can we have both read-gap-locks and insert intention locks on the same gap? If yes, which bad things could happen?

I don't believe the question is the scope of this ticket. In the scope of this ticket nothing wrong happens: no matter how gap is wide (or more widened) SELECT blocked on next record (the one not being deleted) isn't cancelled and this is expected.

Misc

Marko corrected also MDEV-16406, saying that we would actually need 4 lock bits per record heap number if we are going to merge the bitmaps.

midenok commented 4 years ago

Conflict A

Reproduce

--source include/have_innodb.inc
create or replace table t1 (pk int primary key, x int) engine innodb;
insert into t1 values (2, 2);
insert into t1 values (4, 0);
start transaction;
update t1 set x= 2 where pk > 3;
connect (con1,localhost,root,,test);
send select * from t1 for update;
connection default;
--let $wait_condition= select count(*) from information_schema.innodb_lock_waits
--source include/wait_condition.inc
insert into t1 values (1, 2);
insert into t1 values (3, 2);
insert into t1 values (5, 2);
commit;
connection con1;
--echo # No ER_LOCK_DEADLOCK; all rows returned
--error 0, ER_LOCK_DEADLOCK
reap;
show engine innodb status;
connection default;
disconnect con1;
drop table t1;

Result

*** (1) TRANSACTION:
TRANSACTION 41, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1152, 2 row lock(s)
MySQL thread id 9, OS thread handle 140363356845824, query id 6 localhost root Sending data
select * from t1 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 41 lock_mode X waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000004; asc     ;;
1: len 6; hex 000000000028; asc      (;;
2: len 7; hex 0500000139033a; asc     9 :;;
3: len 4; hex 80000002; asc     ;;
*** (2) TRANSACTION:
TRANSACTION 40, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1152, 3 row lock(s), undo log entries 1
MySQL thread id 8, OS thread handle 140363357153024, query id 8 localhost root Update
insert into t1 values (1, 2)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 40 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000004; asc     ;;
1: len 6; hex 000000000028; asc      (;;
2: len 7; hex 0500000139033a; asc     9 :;;
3: len 4; hex 80000002; asc     ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 40 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000002; asc     ;;
1: len 6; hex 000000000024; asc      $;;
2: len 7; hex 830000013702c3; asc     7  ;;
3: len 4; hex 80000002; asc     ;;
*** WE ROLL BACK TRANSACTION (1)

midenok commented 4 years ago

T1

#0  lock_rec_other_has_conflicting (mode=3, block=0x7fa90b7dc3e0, heap_no=3, trx=0x7fa91020a1b8) at /home/midenok/src/mariadb/10.3/src/storage/innobase/lock/lock0lock.cc:1154
#1  0x0000000000e5a5fd in lock_rec_lock (impl=false, mode=3, block=0x7fa90b7dc3e0, heap_no=3, index=0x7fa8a001df40, thr=0x7fa8a002b0e8) at /home/midenok/src/mariadb/10.3/src/storage/innobase/lock/lock0lock.cc:1965
#2  0x0000000000e5ba38 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fa90b7dc3e0, rec=0x7fa90bce4099 "\200", index=0x7fa8a001df40, offsets=0x7fa8e405dff0, mode=LOCK_X, gap_mode=0, thr=0x7fa8a002b0e8) at /home/midenok/src/mariadb/10.3/src/storage/innobase/lock/lock0lock.cc:5843
#3  0x0000000000fc75a4 in sel_set_rec_lock (pcur=0x7fa8a002a8c8, rec=0x7fa90bce4099 "\200", index=0x7fa8a001df40, offsets=0x7fa8e405dff0, mode=3, type=0, thr=0x7fa8a002b0e8, mtr=0x7fa8e405e258) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0sel.cc:1260
#4  0x0000000000fc2e20 in row_search_mvcc (buf=0x7fa8a00134b8 "\375\002", mode=PAGE_CUR_G, prebuilt=0x7fa8a002a700, match_mode=0, direction=1) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0sel.cc:5062
#5  0x0000000000d9b782 in ha_innobase::general_fetch (this=0x7fa8a00214c0, buf=0x7fa8a00134b8 "\375\002", direction=1, match_mode=0) at /home/midenok/src/mariadb/10.3/src/storage/innobase/handler/ha_innodb.cc:9556
#6  0x0000000000d9beb3 in ha_innobase::rnd_next (this=0x7fa8a00214c0, buf=0x7fa8a00134b8 "\375\002") at /home/midenok/src/mariadb/10.3/src/storage/innobase/handler/ha_innodb.cc:9766
#7  0x0000000000b0ab05 in handler::ha_rnd_next (this=0x7fa8a00214c0, buf=0x7fa8a00134b8 "\375\002") at /home/midenok/src/mariadb/10.3/src/sql/handler.cc:2847
#8  0x0000000000cec6d3 in rr_sequential (info=0x7fa8a4012888) at /home/midenok/src/mariadb/10.3/src/sql/records.cc:477
#9  0x00000000006d7cfb in READ_RECORD::read_record (this=0x7fa8a4012888) at /home/midenok/src/mariadb/10.3/src/sql/records.h:69
#10 0x0000000000827328 in sub_select (join=0x7fa8a40113c0, join_tab=0x7fa8a40127c0, end_of_records=false) at /home/midenok/src/mariadb/10.3/src/sql/sql_select.cc:19700
#11 0x000000000080d4c5 in do_select (join=0x7fa8a40113c0, procedure=0x0) at /home/midenok/src/mariadb/10.3/src/sql/sql_select.cc:19221
#12 0x000000000080c1fa in JOIN::exec_inner (this=0x7fa8a40113c0) at /home/midenok/src/mariadb/10.3/src/sql/sql_select.cc:4102
#13 0x000000000080b25e in JOIN::exec (this=0x7fa8a40113c0) at /home/midenok/src/mariadb/10.3/src/sql/sql_select.cc:3896
#14 0x00000000007e1f87 in mysql_select (thd=0x7fa8a4000d58, tables=0x7fa8a4010c68, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fa8a4011398, unit=0x7fa8a4004c10, select_lex=0x7fa8a4005398) at /home/midenok/src/mariadb/10.3/src/sql/sql_select.cc:4301
#15 0x00000000007e17f3 in handle_select (thd=0x7fa8a4000d58, lex=0x7fa8a4004b50, result=0x7fa8a4011398, setup_tables_done_option=0) at /home/midenok/src/mariadb/10.3/src/sql/sql_select.cc:370
#16 0x00000000007a0ba4 in execute_sqlcom_select (thd=0x7fa8a4000d58, all_tables=0x7fa8a4010c68) at /home/midenok/src/mariadb/10.3/src/sql/sql_parse.cc:6293
#17 0x00000000007963af in mysql_execute_command (thd=0x7fa8a4000d58) at /home/midenok/src/mariadb/10.3/src/sql/sql_parse.cc:3820
#18 0x0000000000790ab0 in mysql_parse (thd=0x7fa8a4000d58, rawbuf=0x7fa8a4010a60 "select * from t1 for update", length=27, parser_state=0x7fa8e40625e8, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.3/src/sql/sql_parse.cc:7817

T2

#0  lock_rec_other_has_conflicting (mode=2563, block=0x7fa90b7dc3e0, heap_no=2, trx=0x7fa9102090e8) at /home/midenok/src/mariadb/10.3/src/storage/innobase/lock/lock0lock.cc:1154
#1  0x0000000000e57866 in lock_rec_insert_check_and_lock (flags=0, rec=0x7fa90bce4063 "infimum", block=0x7fa90b7dc3e0, index=0x7fa8a001df40, thr=0x7fa8a007b058, mtr=0x7fa8e40a8c68, inherit=0x7fa8e40a86ad) at /home/midenok/src/mariadb/10.3/src/storage/innobase/lock/lock0lock.cc:5329
#2  0x00000000010d0638 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7fa8e40a9138, entry=0x7fa8a001cdb0, thr=0x7fa8a007b058, mtr=0x7fa8e40a8c68, inherit=0x7fa8e40a86ad) at /home/midenok/src/mariadb/10.3/src/storage/innobase/btr/btr0cur.cc:3173
#3  0x00000000010ce8db in btr_cur_optimistic_insert (flags=0, cursor=0x7fa8e40a9138, offsets=0x7fa8e40a89f8, heap=0x7fa8e40a8c58, entry=0x7fa8a001cdb0, rec=0x7fa8e40a8990, big_rec=0x7fa8e40a9120, n_ext=0, thr=0x7fa8a007b058, mtr=0x7fa8e40a8c68) at /home/midenok/src/mariadb/10.3/src/storage/innobase/btr/btr0cur.cc:3401
#4  0x0000000000f3cf12 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x7fa8a001df40, n_uniq=1, entry=0x7fa8a001cdb0, n_ext=0, thr=0x7fa8a007b058) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0ins.cc:2747
#5  0x0000000000f41b1f in row_ins_clust_index_entry (index=0x7fa8a001df40, entry=0x7fa8a001cdb0, thr=0x7fa8a007b058, n_ext=0) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0ins.cc:3203
#6  0x0000000000f4aff1 in row_ins_index_entry (index=0x7fa8a001df40, entry=0x7fa8a001cdb0, thr=0x7fa8a007b058) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0ins.cc:3328
#7  0x0000000000f4a4e9 in row_ins_index_entry_step (node=0x7fa8a007ae10, thr=0x7fa8a007b058) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0ins.cc:3479
#8  0x0000000000f42f67 in row_ins (node=0x7fa8a007ae10, thr=0x7fa8a007b058) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0ins.cc:3616
#9  0x0000000000f42aa9 in row_ins_step (thr=0x7fa8a007b058) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0ins.cc:3755
#10 0x0000000000f72791 in row_insert_for_mysql (mysql_rec=0x7fa8a002fc48 "\375\001", prebuilt=0x7fa8a007a8e0, ins_mode=ROW_INS_NORMAL) at /home/midenok/src/mariadb/10.3/src/storage/innobase/row/row0mysql.cc:1462
#11 0x0000000000d96f5d in ha_innobase::write_row (this=0x7fa8a002f2a0, record=0x7fa8a002fc48 "\375\001") at /home/midenok/src/mariadb/10.3/src/storage/innobase/handler/ha_innodb.cc:8046
#12 0x0000000000b17601 in handler::ha_write_row (this=0x7fa8a002f2a0, buf=0x7fa8a002fc48 "\375\001") at /home/midenok/src/mariadb/10.3/src/sql/handler.cc:6453
#13 0x000000000074b2e8 in write_record (thd=0x7fa8a0000d28, table=0x7fa8a002e6c8, info=0x7fa8e40aa720) at /home/midenok/src/mariadb/10.3/src/sql/sql_insert.cc:2034
#14 0x0000000000747421 in mysql_insert (thd=0x7fa8a0000d28, table_list=0x7fa8a0013cf8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/midenok/src/mariadb/10.3/src/sql/sql_insert.cc:1072
#15 0x0000000000798785 in mysql_execute_command (thd=0x7fa8a0000d28) at /home/midenok/src/mariadb/10.3/src/sql/sql_parse.cc:4454
#16 0x0000000000790ab0 in mysql_parse (thd=0x7fa8a0000d28, rawbuf=0x7fa8a0013c10 "insert into t1 values (1, 2)", length=28, parser_state=0x7fa8e40ad5e8, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.3/src/sql/sql_parse.cc:7817

midenok commented 3 years ago

Bug: not all records returned by SELECT

Reproduce

--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -5826,6 +5826,7 @@ row_search_mvcc(

 lock_table_wait:
        mtr.commit();
+       DEBUG_SYNC_C("row_search_lock_wait");
        mtr_has_extra_clust_latch = FALSE;

        trx->error_state = err;

--source include/have_innodb.inc
--source include/have_debug.inc

create or replace table t1 (pk int primary key, x int) engine innodb;
insert into t1 values (3, 0);
start transaction;
# 1. Def: X-lock "3" as "next key" (row + gap)
update t1 set x= 1;
connect (con1, localhost, root,, test);
# 2. Con1: Block on "3"
set DEBUG_SYNC= 'row_search_lock_wait WAIT_FOR inserted';
send select * from t1 for update;
connection default;
--let $wait_condition= select count(*) from information_schema.innodb_lock_waits
--source include/wait_condition.inc
# 3. Def: Insert before and after "3"
insert into t1 values (1, 1);
insert into t1 values (2, 1);
insert into t1 values (4, 1);
insert into t1 values (5, 1);
# 4. Def: Unlock "3"
commit;
set DEBUG_SYNC= 'now SIGNAL inserted';
connection con1;
# 5. Con1: Continue SELECT
--echo # No ER_LOCK_DEADLOCK; all rows returned
reap;
connection default;
disconnect con1;
drop table t1;
set DEBUG_SYNC= 'RESET';

Code

--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -3612,6 +3612,9 @@ sel_restore_position_for_mysql(
        ibool           success;

        success = btr_pcur_restore_position(latch_mode, pcur, mtr);
+       DBUG_PRINT("pcur", ("rec: %u", pcur->btr_cur.page_cur.rec[3]));
+       DBUG_PRINT("pcur", ("same_user_rec: %u", success));
+       DBUG_PRINT("pcur", ("rel_pos: %u", pcur->rel_pos));

        *same_user_rec = success;

@@ -5814,6 +5817,7 @@ row_search_mvcc(
                } else {
                        btr_pcur_move_to_next(pcur, &mtr);
                }
+               DBUG_ASSERT(pcur->btr_cur.page_cur.rec[0] == 'i');
                btr_pcur_store_position(pcur, &mtr);
        }
 page_read_error:
@@ -5826,6 +5830,7 @@ row_search_mvcc(

 lock_table_wait:
        mtr.commit();
+       DEBUG_SYNC_C("row_search_lock_wait");
        mtr_has_extra_clust_latch = FALSE;

        trx->error_state = err;
@@ -5846,9 +5851,10 @@ row_search_mvcc(
                }

                if (!dict_index_is_spatial(index)) {
-                       sel_restore_position_for_mysql(
+                       bool r= sel_restore_position_for_mysql(
                                &same_user_rec, BTR_SEARCH_LEAF, pcur,
                                moves_up, &mtr);
+                       DBUG_ASSERT(pcur->btr_cur.page_cur.rec[0] == 'i');
                        /* Counterpart of the stepping backward in lock_wait_or_error.
                        This is linked tight with that btr_pcur_store_position().
                        The jumps to page_read_error: and lock_table_wait: do not get here. */

Placing row_search_lock_wait after mtr.commit() is important. Otherwise INSERT is blocked.

Result

#7  0x00007f10cd633a96 in __GI___assert_fail (assertion=0x1a04323 "pcur->btr_cur.page_cur.rec[0] == 'i'", file=0x1a035fc "/home/midenok/src/mariadb/10.6/src/storage/innobase/row/row0sel.cc", line=5857, function=0x1a03d3b "dberr_t row_search_mvcc(byte *, page_cur_mode_t, row_prebuilt_t *, ulint, ulint)") at assert.c:101
#8  0x00000000013b7219 in row_search_mvcc (buf=0x7f1090204ce8 "\377", mode=PAGE_CUR_G, prebuilt=0x7f109000b928, match_mode=0, direction=0) at /home/midenok/src/mariadb/10.6/src/storage/innobase/row/row0sel.cc:5857
#9  0x000000000116f581 in ha_innobase::index_read (this=0x7f109012a8a0, buf=0x7f1090204ce8 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at ../src/storage/innobase/handler/ha_innodb.cc:8969
#10 0x00000000011701c8 in ha_innobase::index_first (this=0x7f109012a8a0, buf=0x7f1090204ce8 "\377") at ../src/storage/innobase/handler/ha_innodb.cc:9330
#11 0x000000000117043a in ha_innobase::rnd_next (this=0x7f109012a8a0, buf=0x7f1090204ce8 "\377") at ../src/storage/innobase/handler/ha_innodb.cc:9423
#12 0x0000000000ce93cf in handler::ha_rnd_next (this=0x7f109012a8a0, buf=0x7f1090204ce8 "\377") at ../src/sql/handler.cc:3382
#13 0x0000000000effe33 in rr_sequential (info=0x7f1094015888) at ../src/sql/records.cc:519
#14 0x0000000000826f7b in READ_RECORD::read_record (this=0x7f1094015888) at ../src/sql/records.h:81
#15 0x0000000000975d46 in join_init_read_record (tab=0x7f10940157c0) at ../src/sql/sql_select.cc:21971
#16 0x000000000094e265 in sub_select (join=0x7f10940142c0, join_tab=0x7f10940157c0, end_of_records=false) at ../src/sql/sql_select.cc:20993
#17 0x000000000097a244 in do_select (join=0x7f10940142c0, procedure=0x0) at ../src/sql/sql_select.cc:20543
#18 0x0000000000978e95 in JOIN::exec_inner (this=0x7f10940142c0) at ../src/sql/sql_select.cc:4726
#19 0x0000000000977be5 in JOIN::exec (this=0x7f10940142c0) at ../src/sql/sql_select.cc:4504
#20 0x000000000094efbc in mysql_select (thd=0x7f1094000d48, tables=0x7f10940132b0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f1094014298, unit=0x7f10940050a0, select_lex=0x7f1094012cd8) at ../src/sql/sql_select.cc:4982
#21 0x000000000094e79d in handle_select (thd=0x7f1094000d48, lex=0x7f1094004fd8, result=0x7f1094014298, setup_tables_done_option=0) at ../src/sql/sql_select.cc:544
#22 0x0000000000907d43 in execute_sqlcom_select (thd=0x7f1094000d48, all_tables=0x7f10940132b0) at ../src/sql/sql_parse.cc:6254
#23 0x00000000008fd8fc in mysql_execute_command (thd=0x7f1094000d48, is_called_from_prepared_stmt=false) at ../src/sql/sql_parse.cc:3949
#24 0x00000000008f6553 in mysql_parse (thd=0x7f1094000d48, rawbuf=0x7f1094012c40 "select * from t1 for update", length=27, parser_state=0x7f10c2966340) at ../src/sql/sql_parse.cc:8028

frame 8

(gdb) x/16bx pcur->btr_cur.page_cur.rec
0x7f10c30d407e: 0x80    0x00    0x00    0x03    0x00    0x00    0x00    0x00
0x7f10c30d4086: 0x00    0x00    0x80    0x00    0x00    0x00    0x00    0x00

pcur is positioned on "3"

Trace

row_search_mvcc: pcur: rec: 3
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1
row_search_mvcc: pcur: rec: 2
row_search_mvcc: pcur: same_user_rec: 0
row_search_mvcc: pcur: rel_pos: 1

Good

row_search_mvcc: pcur: rec: 3
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1
row_search_mvcc: pcur: rec: 105
row_search_mvcc: pcur: same_user_rec: 0
row_search_mvcc: pcur: rel_pos: 2
row_search_mvcc: pcur: rec: 1
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1
row_search_mvcc: pcur: rec: 2
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1
row_search_mvcc: pcur: rec: 3
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1
row_search_mvcc: pcur: rec: 4
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1
row_search_mvcc: pcur: rec: 5
row_search_mvcc: pcur: same_user_rec: 1
row_search_mvcc: pcur: rel_pos: 1

105 is infimum.

Cause

btr_pcur_restore_position() (from sel_restore_position_for_mysql()) restores record 2 because they are already get inserted. rel_pos in that case is BTR_PCUR_ON and we are advancing to next record (3):

    case BTR_PCUR_ON:
        if (!success && moves_up) {
next:
            if (btr_pcur_move_to_next(pcur, mtr)
                && rec_is_metadata(btr_pcur_get_rec(pcur),
                           *pcur->btr_cur.index)) {
                btr_pcur_move_to_next(pcur, mtr);
            }

            return true;
        }
        return(!success);

In good scenario we restored infimum and advancing to next returned 1. Note that btr_pcur_store_position() cannot store infimum:

    } else if (page_rec_is_infimum_low(offs)) {
        rec = page_rec_get_next(rec);

        if (rec_is_metadata(rec, *index)) {
            ut_ad(!page_has_prev(block->frame));
            rec = page_rec_get_next(rec);
            if (page_rec_is_supremum(rec)) {
                goto before_first;
            }
        }

        cursor->rel_pos = BTR_PCUR_BEFORE;
    } else {

Fix

Remember that we were at infimum, then restore to infimum.

midenok commented 3 years ago

Notes

We jump from here:

        err = sel_set_rec_lock(pcur,
                       rec, index, offsets,
                       prebuilt->select_lock_type,
                       lock_type, thr, &mtr);

        switch (err) {
            const rec_t*    old_vers;
        case DB_SUCCESS_LOCKED_REC:
            if (trx->isolation_level <= TRX_ISO_READ_COMMITTED) {
                /* Note that a record of
                prebuilt->index was locked. */
                prebuilt->new_rec_locks = 1;
            }
            err = DB_SUCCESS;
            /* fall through */
        case DB_SUCCESS:
            break;
        case DB_LOCK_WAIT:
            /* Lock wait for R-tree should already
            be handled in sel_set_rtr_rec_lock() */
            ut_ad(!dict_index_is_spatial(index));
            /* Never unlock rows that were part of a conflict. */
            prebuilt->new_rec_locks = 0;

            if (UNIV_LIKELY(prebuilt->row_read_type
                    != ROW_READ_TRY_SEMI_CONSISTENT)
                || unique_search
                || index != clust_index) {
                if (!prebuilt->skip_locked) {
                    goto lock_wait_or_error;

to there:

lock_wait_or_error:
    if (!dict_index_is_spatial(index)) {
        /* Locked gap may be filled with inserted records.
        Make sure we don't miss them. */
        if (moves_up) {
            btr_pcur_move_to_prev(pcur, &mtr);
        } else {
            btr_pcur_move_to_next(pcur, &mtr);
        }
        DBUG_ASSERT(pcur->btr_cur.page_cur.rec[0] == 'i');
        btr_pcur_store_position(pcur, &mtr);
    }
page_read_error:
    /* Reset the old and new "did semi-consistent read" flags. */
    if (UNIV_UNLIKELY(prebuilt->row_read_type
              == ROW_READ_DID_SEMI_CONSISTENT)) {
        prebuilt->row_read_type = ROW_READ_TRY_SEMI_CONSISTENT;
    }
    did_semi_consistent_read = false;

lock_table_wait:
    mtr.commit();
    DEBUG_SYNC_C("row_search_lock_wait");
    mtr_has_extra_clust_latch = FALSE;

    trx->error_state = err;
    thr->lock_state = QUE_THR_LOCK_ROW;

    if (row_mysql_handle_errors(&err, trx, thr, NULL)) {
        /* It was a lock wait, and it ended */

        thr->lock_state = QUE_THR_LOCK_NOLOCK;
        mtr.start();

        /* Table lock waited, go try to obtain table lock
        again */
        if (table_lock_waited) {
            table_lock_waited = FALSE;

            goto wait_table_again;
        }

        if (!dict_index_is_spatial(index)) {
            bool r= sel_restore_position_for_mysql(
                &same_user_rec, BTR_SEARCH_LEAF, pcur,
                moves_up, &mtr);
            DBUG_ASSERT(pcur->btr_cur.page_cur.rec[0] == 'i');
            /* Counterpart of the stepping backward in lock_wait_or_error.
            This is linked tight with that btr_pcur_store_position().
            The jumps to page_read_error: and lock_table_wait: do not get here. */
            if (same_user_rec) {
                if (!moves_up) {
                    btr_pcur_move_to_prev(pcur, &mtr);
                } else {
                    btr_pcur_move_to_next(pcur, &mtr);
                }
            }
        }

midenok commented 3 years ago

Bug: RQG failure

Reproduce

--source include/have_innodb.inc
--source include/have_debug.inc

set @saved_frequency= @@global.innodb_purge_rseg_truncate_frequency;
set global innodb_purge_rseg_truncate_frequency= 1;

create table t1 (a int primary key) engine innodb;
insert into t1 (a) values (1);

connect (con_purge, localhost, root,, test);
start transaction with consistent snapshot;
connection default;

delete from t1;

connect (con_rollback, localhost, root,, test);
set DEBUG_SYNC= 'rollback_undo_pk SIGNAL rollback WAIT_FOR inserted';
send insert into t1 values (1), (1);

connect (con_tamper, localhost, root,, test);
set DEBUG_SYNC= 'now WAIT_FOR rollback';
set DEBUG_SYNC= 'row_mysql_handle_errors SIGNAL waiting';
send insert into t1 values (2), (1);

connection con_purge;
set DEBUG_SYNC= 'now WAIT_FOR waiting';
commit;
--source include/wait_all_purged.inc
disconnect con_purge;

connection con_tamper;
reap;
set DEBUG_SYNC= 'now SIGNAL inserted';
disconnect con_tamper;

connection con_rollback;
--error ER_DUP_ENTRY
reap;
disconnect con_rollback;

drop table t1;
set DEBUG_SYNC= 'RESET';
set global innodb_purge_rseg_truncate_frequency= @saved_frequency;

Result

#3  0x000032ba1604ef36 in __GI___assert_fail (assertion=0x560a08b36880 "rec_get_deleted_flag(btr_pcur_get_rec(pcur), (node->table)->not_redundant())", file=0x560a08b35d20 "/data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc", line=385, function=0x560a08b364a0 "dberr_t row_undo_mod_clust(undo_node_t*, que_thr_t*)") at assert.c:101
#4  0x0000560a07afa56a in row_undo_mod_clust (node=0x61a0003ca908, thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:385
#5  0x0000560a07b00f65 in row_undo_mod (node=0x61a0003ca908, thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:1408
#6  0x0000560a0774072b in row_undo (node=0x61a0003ca908, thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:444
#7  0x0000560a07740c1a in row_undo_step (thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:496
#8  0x0000560a075eac84 in que_thr_step (thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:651
#9  0x0000560a075eb048 in que_run_threads_low (thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:709
#10 0x0000560a075eb1ea in que_run_threads (thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:729
#11 0x0000560a077ddebb in trx_t::rollback_low (this=0x76f1193aeb68, savept=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:131
#12 0x0000560a077d82a2 in trx_rollback_for_mysql_low (trx=0x76f1193aeb68) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:196
#13 0x0000560a077d88b4 in trx_rollback_for_mysql (trx=0x76f1193aeb68) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:227
#14 0x0000560a0732993f in innobase_rollback (hton=0x615000002b18, thd=0x62b0000bd218, rollback_trx=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:4560
#15 0x0000560a06a1acfc in ha_rollback_trans (thd=0x62b0000bd218, all=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:2153
#16 0x0000560a066a2a6e in trans_rollback_stmt (thd=0x62b0000bd218) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/transaction.cc:535
#17 0x0000560a06288419 in mysql_execute_command (thd=0x62b0000bd218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:6048
#18 0x0000560a062940ce in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "INSERT INTO t1 (a) VALUES ( 1), ( 382) /* E_R Thread2 QNO 3792 CON_ID 15 */", length=75, parser_state=0x208e3c517b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8028

frame 4

385                     ut_ad(rec_get_deleted_flag(btr_pcur_get_rec(pcur),
386                                                dict_table_is_comp(node->table)));

midenok commented 3 years ago

Bad

#0  rec_get_bit_field_1 (rec=0x654c4b9b226f "\200", offs=5, mask=32, shift=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/rem0rec.ic:137
#1  0x0000560a07af5b4f in rec_get_deleted_flag (rec=0x654c4b9b226f "\200", comp=1) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/rem0rec.ic:564
#2  0x0000560a07afa49d in row_undo_mod_clust (node=0x61a0003ca908, thr=0x61600711bbc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:385

126     /******************************************************//**
127     Gets a bit field from within 1 byte. */
128     UNIV_INLINE
129     byte
130     rec_get_bit_field_1(
131     /*================*/
132             const rec_t*    rec,    /*!< in: pointer to record origin */
133             ulint           offs,   /*!< in: offset from the origin down */
134             ulint           mask,   /*!< in: mask used to filter bits */
135             ulint           shift)  /*!< in: shift right applied after masking */
136     {
137       return static_cast<byte>((*(rec - offs) & mask) >> shift);
138     }

(rr) p offs
$29 = 5
(rr) p mask
$30 = 32
(rr) p shift
$31 = 0
(rr) x/6bx (rec - 5)
0x654c4b9b226a: 0x00    0x0c    0x68    0xf9    0xfc    0x80

Good

#0  rec_get_bit_field_1 (rec=0x654c4b9b226f "\200", offs=5, mask=32, shift=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/rem0rec.ic:137
#1  0x0000560a07af5b4f in rec_get_deleted_flag (rec=0x654c4b9b226f "\200", comp=1) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/rem0rec.ic:564
#2  0x0000560a07afa49d in row_undo_mod_clust (node=0x61a00038cb08, thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:385
#3  0x0000560a07b00f65 in row_undo_mod (node=0x61a00038cb08, thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:1408
#4  0x0000560a0774072b in row_undo (node=0x61a00038cb08, thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:444
#5  0x0000560a07740c1a in row_undo_step (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:496
#6  0x0000560a075eac84 in que_thr_step (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:651
#7  0x0000560a075eb048 in que_run_threads_low (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:709
#8  0x0000560a075eb1ea in que_run_threads (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:729
#9  0x0000560a077ddebb in trx_t::rollback_low (this=0x76f1193ada48, savept=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:131
#10 0x0000560a077d82a2 in trx_rollback_for_mysql_low (trx=0x76f1193ada48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:196
#11 0x0000560a077d88b4 in trx_rollback_for_mysql (trx=0x76f1193ada48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:227
#12 0x0000560a0732993f in innobase_rollback (hton=0x615000002b18, thd=0x62b0000d9218, rollback_trx=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:4560
#13 0x0000560a06a1acfc in ha_rollback_trans (thd=0x62b0000d9218, all=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:2153
#14 0x0000560a066a2a6e in trans_rollback_stmt (thd=0x62b0000d9218) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/transaction.cc:535
#15 0x0000560a06288419 in mysql_execute_command (thd=0x62b0000d9218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:6048
#16 0x0000560a062940ce in mysql_parse (thd=0x62b0000d9218, rawbuf=0x62b0000a8238 "INSERT INTO t1 (a) VALUES ( 1), ( 383) /* E_R Thread1 QNO 3280 CON_ID 14 */", length=75, parser_state=0x15511511cb20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8028

(rr) p offs
$32 = 5
(rr) p mask
$33 = 32
(rr) p shift
$34 = 0
(rr) x/6bx (rec - 5)
0x654c4b9b226a: 0x20    0x0c    0x68    0xf9    0xfc    0x80

midenok commented 3 years ago

Good: (rec - 5) written

#0  0x0000560a075992a9 in mtr_t::write<1u, (mtr_t::write_type)1, unsigned long> (this=0x15511511af50, block=..., ptr=0x654c4b9b226a, val=32) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/mtr0log.h:209
#1  0x0000560a0788f257 in btr_cur_upd_rec_in_place (rec=0x654c4b9b226f "\200", index=0x616001eaed08, offsets=0x6140000d5ec8, update=0x6180001e1508, block=0x654c4aff1720, mtr=0x15511511af50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4147
#2  0x0000560a078915a9 in btr_cur_update_in_place (flags=7, cursor=0x61a00038cb78, offsets=0x6140000d5ec8, update=0x6180001e1508, cmpl_info=0, thr=0x616005ee0dc0, trx_id=9534, mtr=0x15511511af50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4355
#3  0x0000560a0789447a in btr_cur_optimistic_update (flags=7, cursor=0x61a00038cb78, offsets=0x15511511ae70, heap=0x15511511ae50, update=0x6180001e1508, cmpl_info=0, thr=0x616005ee0dc0, trx_id=9534, mtr=0x15511511af50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4598
#4  0x0000560a07af7e7b in row_undo_mod_clust_low (node=0x61a00038cb08, offsets=0x15511511ae70, offsets_heap=0x15511511ae50, heap=0x6190006a4f80, rebuilt_old_pk=0x15511511ae90, sys=0x15511511b490 "\300\264\021\025Q\025", thr=0x616005ee0dc0, mtr=0x15511511af50, mode=2) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:132
#5  0x0000560a07af9a97 in row_undo_mod_clust (node=0x61a00038cb08, thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:301
#6  0x0000560a07b00f65 in row_undo_mod (node=0x61a00038cb08, thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:1408
#7  0x0000560a0774072b in row_undo (node=0x61a00038cb08, thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:444
#8  0x0000560a07740c1a in row_undo_step (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:496
#9  0x0000560a075eac84 in que_thr_step (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:651
#10 0x0000560a075eb048 in que_run_threads_low (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:709
#11 0x0000560a075eb1ea in que_run_threads (thr=0x616005ee0dc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:729
#12 0x0000560a077ddebb in trx_t::rollback_low (this=0x76f1193ada48, savept=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:131
#13 0x0000560a077d82a2 in trx_rollback_for_mysql_low (trx=0x76f1193ada48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:196
#14 0x0000560a077d88b4 in trx_rollback_for_mysql (trx=0x76f1193ada48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:227
#15 0x0000560a0732993f in innobase_rollback (hton=0x615000002b18, thd=0x62b0000d9218, rollback_trx=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:4560
#16 0x0000560a06a1acfc in ha_rollback_trans (thd=0x62b0000d9218, all=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:2153
#17 0x0000560a066a2a6e in trans_rollback_stmt (thd=0x62b0000d9218) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/transaction.cc:535
#18 0x0000560a06288419 in mysql_execute_command (thd=0x62b0000d9218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:6048
#19 0x0000560a062940ce in mysql_parse (thd=0x62b0000d9218, rawbuf=0x62b0000a8238 "INSERT INTO t1 (a) VALUES ( 1), ( 383) /* E_R Thread1 QNO 3280 CON_ID 14 */", length=75, parser_state=0x15511511cb20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8028

The divergence is #5 row_undo_mod_clust(): 301 vs 385

frame 5

298             /* Try optimistic processing of the record, keeping changes within
299             the index page */
300
301             err = row_undo_mod_clust_low(node, &offsets, &offsets_heap,
302                                          heap, &rebuilt_old_pk, sys,
303                                          thr, &mtr, online
304                                          ? BTR_MODIFY_LEAF | BTR_ALREADY_S_LATCHED
305                                          : BTR_MODIFY_LEAF);
306
307             if (err != DB_SUCCESS) {
308                     btr_pcur_commit_specify_mtr(pcur, &mtr);
309
310                     /* We may have to modify tree structure: do a pessimistic
311                     descent down the index tree */

Good and Bad are both optimistic success.

frame 1

4150                    mtr->write<1,mtr_t::MAYBE_NOP>(*block, info_bits,
4151                                                   (*info_bits
4152                                                    & ~REC_INFO_BITS_MASK)
4153                                                   | update->info_bits);

(rr) p/x update->info_bits
$40 = 0x20

Bad

(rr) p/x update->info_bits
$42 = 0x20

midenok commented 3 years ago

Bad: (rec - 5) overwritten with 0

#0  ut_align_down (ptr=0x654c4b9b226f, alignment=32768) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/ut0byte.h:69
#1  0x0000560a073835ac in page_align (ptr=0x654c4b9b226f) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0page.h:203
#2  0x0000560a073835d2 in page_align (ptr=0x654c4b9b226f) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0page.h:207
#3  0x0000560a07318993 in page_rec_check (rec=0x654c4b9b226f "\200") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0page.ic:376
#4  0x0000560a07383d80 in page_rec_is_infimum (rec=0x654c4b9b226f "\200") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0page.ic:179
#5  0x0000560a078b2a81 in page_rec_get_prev_const (rec=0x654c4b9b226f "\200") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0page.ic:527
#6  0x0000560a078b2c06 in page_rec_get_prev (rec=0x654c4b9b226f "\200") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0page.ic:564
#7  0x0000560a078b384e in page_cur_move_to_prev (cur=0x6200000332f0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0cur.ic:192
#8  0x0000560a078b4c89 in btr_pcur_move_to_prev_on_page (cursor=0x6200000332e8) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/btr0pcur.ic:260
#9  0x0000560a078b98ce in btr_pcur_move_to_prev (cursor=0x6200000332e8, mtr=0x15511511ae30) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0pcur.cc:629
#10 0x0000560a07734a24 in row_search_mvcc (buf=0x6190000b54c8 "\377", mode=PAGE_CUR_GE, prebuilt=0x620000033108, match_mode=1, direction=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0sel.cc:5817
#11 0x0000560a07341be1 in ha_innobase::index_read (this=0x61d0007b84b8, buf=0x6190000b54c8 "\377", key_ptr=0x621000a34a00 "\001", key_len=4, find_flag=HA_READ_KEY_EXACT) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:8969
#12 0x0000560a0687944b in handler::index_read_map (this=0x61d0007b84b8, buf=0x6190000b54c8 "\377", key=0x621000a34a00 "\001", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.h:3954
#13 0x0000560a06a23cf2 in handler::ha_index_read_map (this=0x61d0007b84b8, buf=0x6190000b54c8 "\377", key=0x621000a34a00 "\001", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:3439
#14 0x0000560a06a38b8a in handler::read_range_first (this=0x61d0007b84b8, start_key=0x61d0007b85b8, end_key=0x61d0007b85d8, eq_range_arg=true, sorted=true) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:6546
#15 0x0000560a0672c249 in handler::multi_range_read_next (this=0x61d0007b84b8, range_info=0x15511511b610) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/multi_range_read.cc:516
#16 0x0000560a0672c596 in Mrr_simple_index_reader::get_next (this=0x61d0007b8ae0, range_info=0x15511511b610) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/multi_range_read.cc:553
#17 0x0000560a06735565 in DsMrr_impl::dsmrr_next (this=0x61d0007b8990, range_info=0x15511511b610) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/multi_range_read.cc:1653
#18 0x0000560a0737074a in ha_innobase::multi_range_read_next (this=0x61d0007b84b8, range_info=0x15511511b610) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:19712
#19 0x0000560a06e015de in QUICK_RANGE_SELECT::get_next (this=0x613000313a00) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/opt_range.cc:12647
#20 0x0000560a06e32685 in rr_quick (info=0x15511511ba40) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/records.cc:403
#21 0x0000560a060e71b2 in READ_RECORD::read_record (this=0x15511511ba40) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/records.h:81
#22 0x0000560a06555fb7 in mysql_update (thd=0x62b0000d9218, table_list=0x62b0000a83a8, fields=..., values=..., conds=0x62b0000a9488, order_num=0, order=0x0, limit=18446744073709551615, ignore=false, found_return=0x15511511c270, updated_return=0x15511511c290) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_update.cc:863
#23 0x0000560a0627bbcf in mysql_execute_command (thd=0x62b0000d9218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:4411
#24 0x0000560a062940ce in mysql_parse (thd=0x62b0000d9218, rawbuf=0x62b0000a8238 "UPDATE t1 SET a = 1 WHERE a = 317 OR a = 1 /* E_R Thread1 QNO 3461 CON_ID 14 */", length=79, parser_state=0x15511511cb20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8028

63      /** Round down a pointer to the nearest aligned address.
64      @param ptr        pointer
65      @param alignment  a power of 2
66      @return aligned pointer */
67      static inline void *ut_align_down(void *ptr, size_t alignment)
68      {
69        ut_ad(alignment > 0);
70        ut_ad(ut_is_2pow(alignment));
71        ut_ad(ptr);
72        static_assert(sizeof ptr == sizeof(size_t), "compatibility");
73
74        return reinterpret_cast<void*>(reinterpret_cast<size_t>(ptr) &
75                                       ~(alignment - 1));
76      }

(rr) p ptr
$44 = (void *) 0x654c4b9b226f
(rr) p alignment
$45 = 32768

midenok commented 3 years ago

Cause

365             btr_pcur_commit_specify_mtr(pcur, &mtr);
366             DEBUG_SYNC_C("rollback_undo_pk");
367
368             if (err != DB_SUCCESS) {
369                     goto func_exit;
370             }
371
372             /* FIXME: Perform the below operations in the above
373             mini-transaction when possible. */
374
375             if (node->rec_type == TRX_UNDO_UPD_DEL_REC) {
376                     /* In delete-marked records, DB_TRX_ID must
377                     always refer to an existing update_undo log record. */
378                     ut_ad(node->new_trx_id);
379
380                     mtr.start();
381                     if (!btr_pcur_restore_position(BTR_MODIFY_LEAF, pcur, &mtr)) {
382                             goto mtr_commit_exit;
383                     }
384
385                     ut_ad(rec_get_deleted_flag(btr_pcur_get_rec(pcur),
386                                                dict_table_is_comp(node->table)));

Latch is released at 365, then another thread changes the record and assertion fails at 385

Failing thread

#9  0x0000754626bcf8a3 in syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#10 0x000055751f4f95ea in srw_mutex::wake (this=0x1d510fe527a0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/sync/srw_lock.cc:225
#11 0x000055751f0e3678 in srw_mutex::wr_unlock (this=0x1d510fe527a0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/srw_lock.h:77
#12 0x000055751f0e3a3f in ssux_lock_low::wr_unlock (this=0x1d510fe527a0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/srw_lock.h:251
#13 0x000055751f0f6782 in sux_lock<ssux_lock_low>::u_or_x_unlock (this=0x1d510fe527a0, allow_readers=false, claim_ownership=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/sux_lock.h:259
#14 0x000055751f2b76e1 in buf_page_release_latch (block=0x1d510fe52720, rw_latch=2) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/buf0buf.ic:291
#15 0x000055751f2c2067 in ReleaseLatches::operator() (this=0x7fd45b126bc0, slot=0x7fd45b126fb0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/mtr/mtr0mtr.cc:284
#16 0x000055751f2c837b in CIterate<ReleaseLatches>::operator() (this=0x7fd45b126bc0, block=0x7fd45b126f90) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/mtr/mtr0mtr.cc:61
#17 0x000055751f2c5abd in mtr_buf_t::for_each_block_in_reverse<CIterate<ReleaseLatches> > (this=0x7fd45b126f68, functor=...) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/dyn0buf.h:379
#18 0x000055751f2b921e in mtr_t::commit (this=0x7fd45b126f50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/mtr/mtr0mtr.cc:450
#19 0x000055751f85c0d4 in btr_pcur_commit_specify_mtr (pcur=0x61a000196f78, mtr=0x7fd45b126f50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/btr0pcur.ic:345
#20 0x000055751f85f873 in row_undo_mod_clust (node=0x61a000196f08, thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:365
#21 0x000055751f86656f in row_undo_mod (node=0x61a000196f08, thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:1408
#22 0x000055751f4a900e in row_undo (node=0x61a000196f08, thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:426
#23 0x000055751f4a94fd in row_undo_step (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:478
#24 0x000055751f351b42 in que_thr_step (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:651
#25 0x000055751f351f06 in que_run_threads_low (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:709
#26 0x000055751f3520a8 in que_run_threads (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:729
#27 0x000055751f544ecb in trx_t::rollback_low (this=0x7eb201405b48, savept=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:125
#28 0x000055751f53f772 in trx_rollback_for_mysql_low (trx=0x7eb201405b48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:190
#29 0x000055751f53fd84 in trx_rollback_for_mysql (trx=0x7eb201405b48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:221
#30 0x000055751f090278 in innobase_rollback (hton=0x615000002b18, thd=0x62b0000cb218, rollback_trx=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:4563
#31 0x000055751e7a90e0 in ha_rollback_trans (thd=0x62b0000cb218, all=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:2153
#32 0x000055751e408f68 in trans_rollback_stmt (thd=0x62b0000cb218) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/transaction.cc:535
#33 0x000055751dfed7ed in mysql_execute_command (thd=0x62b0000cb218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:6046
#34 0x000055751dff94a2 in mysql_parse (thd=0x62b0000cb218, rawbuf=0x62b0000d2238 "INSERT INTO t1 (a) VALUES ( 1), ( 1) /* E_R Thread1 QNO 14 CON_ID 14 */", length=71, parser_state=0x7fd45b128b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8026

Tampering thread

#0  memcpy () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:145
145     ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S: No such file or directory.
#0  memcpy () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:145
#1  0x00003e9623cdf36f in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
#2  0x000055751f2ec98b in page_cur_insert_rec_low (cur=0x52aa47095458, index=0x616001e6fa08, rec=0x610000011acd "\200", offsets=0x52aa47095580, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/page/page0cur.cc:1451
#3  0x000055751f5d97fc in page_cur_tuple_insert (cursor=0x52aa47095458, tuple=0x616001ea4208, index=0x616001e6fa08, offsets=0x52aa47095410, heap=0x52aa470953f0, n_ext=0, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0cur.ic:285
#4  0x000055751f5f1225 in btr_cur_optimistic_insert (flags=0, cursor=0x52aa47095450, offsets=0x52aa47095410, heap=0x52aa470953f0, entry=0x616001ea4208, rec=0x52aa47095430, big_rec=0x52aa470953d0, n_ext=0, thr=0x6200001c3868, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:3561
#5  0x000055751f3d38df in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x616001e6fa08, n_uniq=1, entry=0x616001ea4208, n_ext=0, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:2762
#6  0x000055751f3d5fb2 in row_ins_clust_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868, n_ext=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3235
#7  0x000055751f3d68b1 in row_ins_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3361
#8  0x000055751f3d78fa in row_ins_index_entry_step (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3530
#9  0x000055751f3d82b9 in row_ins (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3676
#10 0x000055751f3d93e1 in row_ins_step (thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3822
#11 0x000055751f418a13 in row_insert_for_mysql (mysql_rec=0x61900044cfc8 "\377\001", prebuilt=0x6200001c3108, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0mysql.cc:1342
#12 0x000055751f0a1c61 in ha_innobase::write_row (this=0x61d0008322b8, record=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:7781
#13 0x000055751e7ce1dc in handler::ha_write_row (this=0x61d0008322b8, buf=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:7500
#14 0x000055751df2ce35 in write_record (thd=0x62b000149218, table=0x61900044ca98, info=0x52aa47096e60, sink=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:2113
#15 0x000055751df2572d in mysql_insert (thd=0x62b000149218, table_list=0x62b0001183a0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:1104
#16 0x000055751dfe2129 in mysql_execute_command (thd=0x62b000149218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:4566
#17 0x000055751dff94a2 in mysql_parse (thd=0x62b000149218, rawbuf=0x62b000118238 "INSERT INTO t1 (a) VALUES ( 378), ( 1) /* E_R Thread2 QNO 30 CON_ID 18 */", length=73, parser_state=0x52aa47097b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8026

midenok commented 3 years ago

1. thread 18: record S-locked

#0  lock_rec_lock (impl=false, mode=1026, block=0x1d510fe52720, heap_no=23, index=0x616001e6fa08, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/lock/lock0lock.cc:1479
#1  0x000055751f22b9d6 in lock_clust_rec_read_check_and_lock (flags=0, block=0x1d510fe52720, rec=0x1d511081024b "\200", index=0x616001e6fa08, offsets=0x52aa47094fd0, mode=LOCK_S, gap_mode=1024, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/lock/lock0lock.cc:5313
#2  0x000055751f3ccc10 in row_ins_set_shared_rec_lock (type=1024, block=0x1d510fe52720, rec=0x1d511081024b "\200", index=0x616001e6fa08, offsets=0x52aa47094fd0, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:1404
#3  0x000055751f3d0d94 in row_ins_duplicate_error_in_clust (flags=0, cursor=0x52aa47095450, entry=0x616001ea4208, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:2329
#4  0x000055751f3d35be in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x616001e6fa08, n_uniq=1, entry=0x616001ea4208, n_ext=0, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:2724
#5  0x000055751f3d5fb2 in row_ins_clust_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868, n_ext=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3235
#6  0x000055751f3d68b1 in row_ins_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3361
#7  0x000055751f3d78fa in row_ins_index_entry_step (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3530
#8  0x000055751f3d82b9 in row_ins (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3676
#9  0x000055751f3d93e1 in row_ins_step (thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3822
#10 0x000055751f418a13 in row_insert_for_mysql (mysql_rec=0x61900044cfc8 "\377\001", prebuilt=0x6200001c3108, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0mysql.cc:1342
#11 0x000055751f0a1c61 in ha_innobase::write_row (this=0x61d0008322b8, record=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:7781
#12 0x000055751e7ce1dc in handler::ha_write_row (this=0x61d0008322b8, buf=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:7500
#13 0x000055751df2ce35 in write_record (thd=0x62b000149218, table=0x61900044ca98, info=0x52aa47096e60, sink=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:2113
#14 0x000055751df2572d in mysql_insert (thd=0x62b000149218, table_list=0x62b0001183a0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:1104
#15 0x000055751dfe2129 in mysql_execute_command (thd=0x62b000149218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:4566
#16 0x000055751dff94a2 in mysql_parse (thd=0x62b000149218, rawbuf=0x62b000118238 "INSERT INTO t1 (a) VALUES ( 378), ( 1) /* E_R Thread2 QNO 30 CON_ID 18 */", length=73, parser_state=0x52aa47097b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8026

(rr) p LOCK_S|LOCK_REC_NOT_GAP
$32 = 1026

2. thread 18: record X-lock failed (DB_LOCK_WAIT)

#0  lock_rec_lock (impl=true, mode=1027, block=0x1d510fe52720, heap_no=23, index=0x616001e6fa08, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/lock/lock0lock.cc:1479
#1  0x000055751f229b49 in lock_clust_rec_modify_check_and_lock (block=0x1d510fe52720, rec=0x1d511081024b "\200", index=0x616001e6fa08, offsets=0x52aa47095580, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/lock/lock0lock.cc:5059
#2  0x000055751f5f3504 in btr_cur_upd_lock_and_undo (flags=0, cursor=0x52aa47095450, offsets=0x52aa47095580, update=0x619000477d08, cmpl_info=0, thr=0x6200001c3868, mtr=0x52aa47095860, roll_ptr=0x52aa47094770) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:3883
#3  0x000055751f5f6c46 in btr_cur_update_in_place (flags=0, cursor=0x52aa47095450, offsets=0x52aa47095580, update=0x619000477d08, cmpl_info=0, thr=0x6200001c3868, trx_id=90, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4307
#4  0x000055751f5f9f94 in btr_cur_optimistic_update (flags=0, cursor=0x52aa47095450, offsets=0x52aa47095410, heap=0x52aa470953f0, update=0x619000477d08, cmpl_info=0, thr=0x6200001c3868, trx_id=90, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4601
#5  0x000055751f3c67af in row_ins_clust_index_entry_by_modify (pcur=0x52aa47095450, flags=0, mode=2, offsets=0x52aa47095410, offsets_heap=0x52aa470953f0, heap=0x619000477c80, entry=0x616001ea4208, thr=0x6200001c3868, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:323
#6  0x000055751f3d3722 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x616001e6fa08, n_uniq=1, entry=0x616001ea4208, n_ext=0, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:2743
#7  0x000055751f3d5fb2 in row_ins_clust_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868, n_ext=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3235
#8  0x000055751f3d68b1 in row_ins_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3361
#9  0x000055751f3d78fa in row_ins_index_entry_step (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3530
#10 0x000055751f3d82b9 in row_ins (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3676
#11 0x000055751f3d93e1 in row_ins_step (thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3822
#12 0x000055751f418a13 in row_insert_for_mysql (mysql_rec=0x61900044cfc8 "\377\001", prebuilt=0x6200001c3108, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0mysql.cc:1342
#13 0x000055751f0a1c61 in ha_innobase::write_row (this=0x61d0008322b8, record=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:7781
#14 0x000055751e7ce1dc in handler::ha_write_row (this=0x61d0008322b8, buf=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:7500
#15 0x000055751df2ce35 in write_record (thd=0x62b000149218, table=0x61900044ca98, info=0x52aa47096e60, sink=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:2113
#16 0x000055751df2572d in mysql_insert (thd=0x62b000149218, table_list=0x62b0001183a0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:1104
#17 0x000055751dfe2129 in mysql_execute_command (thd=0x62b000149218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:4566
#18 0x000055751dff94a2 in mysql_parse (thd=0x62b000149218, rawbuf=0x62b000118238 "INSERT INTO t1 (a) VALUES ( 378), ( 1) /* E_R Thread2 QNO 30 CON_ID 18 */", length=73, parser_state=0x52aa47097b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8026

3. thread 9: Purge thread updates PAGE_FREE field to point to record 23

#0  mach_write_to_2 (b=0x1d511081002c "\002K", n=587) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/mach0data.ic:63
#1  0x000055751f2f310c in page_mem_free (block=..., rec=0x1d511081024b "\200", data_size=17, extra_size=5) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/page/page0cur.cc:2098
#2  0x000055751f2f43c9 in page_cur_delete_rec (cursor=0x61a00000a9b0, index=0x616001e6fa08, offsets=0x66c81e03e4e0, mtr=0x66c81e03ebf0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/page/page0cur.cc:2280
#3  0x000055751f6013d6 in btr_cur_optimistic_delete_func (cursor=0x61a00000a9a8, flags=0, mtr=0x66c81e03ebf0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:5610
#4  0x000055751f4590c7 in row_purge_remove_clust_if_poss_low (node=0x61a00000a908, mode=2) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0purge.cc:229
#5  0x000055751f45946e in row_purge_remove_clust_if_poss (node=0x61a00000a908) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0purge.cc:276
#6  0x000055751f45b639 in row_purge_del_mark (node=0x61a00000a908) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0purge.cc:735
#7  0x000055751f45f29d in row_purge_record_func (node=0x61a00000a908, undo_rec=0x621000049d88 "", thr=0x6160000589c0, updated_extern=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0purge.cc:1163
#8  0x000055751f45f8f0 in row_purge (node=0x61a00000a908, undo_rec=0x621000049d88 "", thr=0x6160000589c0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0purge.cc:1224
#9  0x000055751f45fce3 in row_purge_step (thr=0x6160000589c0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0purge.cc:1273
#10 0x000055751f351b5e in que_thr_step (thr=0x6160000589c0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:653
#11 0x000055751f351f06 in que_run_threads_low (thr=0x6160000589c0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:709
#12 0x000055751f3520a8 in que_run_threads (thr=0x6160000589c0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:729
#13 0x000055751f4e085c in srv_task_execute () at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/srv/srv0srv.cc:1756
#14 0x000055751f4e1684 in purge_worker_callback () at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/srv/srv0srv.cc:1915

frame 9

1264            node = static_cast<purge_node_t*>(thr->run_node);
1265
1266            node->start();
1267
1268            if (!node->undo_recs.empty()) {
1269                    trx_purge_rec_t purge_rec = node->undo_recs.front();
1270                    node->undo_recs.pop();
1271                    node->roll_ptr = purge_rec.roll_ptr;
1272
1273                    row_purge(node, purge_rec.undo_rec, thr);
1274
1275                    if (node->undo_recs.empty()) {
1276                            row_purge_end(thr);
1277                    } else {
1278                            thr->run_node = node;
1279                    }
1280            } else {
1281                    row_purge_end(thr);
1282            }

(rr) p node
$140 = (purge_node_t *) 0x61a00000a908
(rr) p purge_rec
$131 = {
  undo_rec = 0x621000049d88 "",
  roll_ptr = 13229323927486736
}
(rr) p node->undo_recs
$133 = std::queue wrapping: std::deque with 1 element = {{
    undo_rec = 0x621000049db8 "",
    roll_ptr = 13229323927486770
  }}

4. thread 18: btr_cur_optimistic_insert(): locking heap_no 2

#0  lock_rec_insert_check_and_lock (rec=0x1d5110810063 "infimum", block=0x1d510fe52720, index=0x616001e6fa08, thr=0x6200001c3868, mtr=0x52aa47095860, inherit=0x52aa47094c40) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/lock/lock0lock.cc:4783
#1  0x000055751f5eef57 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x52aa47095450, entry=0x616001ea4208, thr=0x6200001c3868, mtr=0x52aa47095860, inherit=0x52aa47094c40) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:3283
#2  0x000055751f5f082c in btr_cur_optimistic_insert (flags=0, cursor=0x52aa47095450, offsets=0x52aa47095410, heap=0x52aa470953f0, entry=0x616001ea4208, rec=0x52aa47095430, big_rec=0x52aa470953d0, n_ext=0, thr=0x6200001c3868, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:3527
#3  0x000055751f3d38df in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x616001e6fa08, n_uniq=1, entry=0x616001ea4208, n_ext=0, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:2762
#4  0x000055751f3d5fb2 in row_ins_clust_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868, n_ext=0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3235
#5  0x000055751f3d68b1 in row_ins_index_entry (index=0x616001e6fa08, entry=0x616001ea4208, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3361
#6  0x000055751f3d78fa in row_ins_index_entry_step (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3530
#7  0x000055751f3d82b9 in row_ins (node=0x6200001c3630, thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3676
#8  0x000055751f3d93e1 in row_ins_step (thr=0x6200001c3868) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0ins.cc:3822
#9  0x000055751f418a13 in row_insert_for_mysql (mysql_rec=0x61900044cfc8 "\377\001", prebuilt=0x6200001c3108, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0mysql.cc:1342
#10 0x000055751f0a1c61 in ha_innobase::write_row (this=0x61d0008322b8, record=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:7781
#11 0x000055751e7ce1dc in handler::ha_write_row (this=0x61d0008322b8, buf=0x61900044cfc8 "\377\001") at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:7500
#12 0x000055751df2ce35 in write_record (thd=0x62b000149218, table=0x61900044ca98, info=0x52aa47096e60, sink=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:2113
#13 0x000055751df2572d in mysql_insert (thd=0x62b000149218, table_list=0x62b0001183a0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_insert.cc:1104
#14 0x000055751dfe2129 in mysql_execute_command (thd=0x62b000149218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:4566
#15 0x000055751dff94a2 in mysql_parse (thd=0x62b000149218, rawbuf=0x62b000118238 "INSERT INTO t1 (a) VALUES ( 378), ( 1) /* E_R Thread2 QNO 30 CON_ID 18 */", length=73, parser_state=0x52aa47097b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8026

(rr) p g.cell()
$83 = (hash_cell_t &) @0x62e000003b28: {
  node = 0x7eb201405bd8
}
(rr) p id
$84 = {
  m_id = 25769803779
}
(rr) p heap_no
$88 = 2

5. getting free page record

#0  page_cur_insert_rec_low (cur=0x52aa47095458, index=0x616001e6fa08, rec=0x610000011acd "\200", offsets=0x52aa47095580, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/page/page0cur.cc:1369
#1  0x000055751f5d97fc in page_cur_tuple_insert (cursor=0x52aa47095458, tuple=0x616001ea4208, index=0x616001e6fa08, offsets=0x52aa47095410, heap=0x52aa470953f0, n_ext=0, mtr=0x52aa47095860) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/include/page0cur.ic:285

1341      if (rec_t* free_rec= page_header_get_ptr(block->frame, PAGE_FREE))
1342      {
....
1365        if (comp)
1366        {
1367          heap_no= rec_get_heap_no_new(free_rec);
1368          uint16_t next= mach_read_from_2(free_rec - REC_NEXT);
1369          mach_write_to_2(page_free, next
1370                          ? static_cast<uint16_t>(free_rec + next - block->frame)
1371                          : 0);
1372        }

(rr) p heap_no
$108 = 23
(rr) p block
$109 = (buf_block_t *) 0x1d510fe52720
(rr) p page_header_get_offs(block->frame, PAGE_FREE)
$103 = 587
(rr) x/2bx page_free
0x1d511081002c: 0x02    0x4b
(rr) p 0x24b
$107 = 587
(rr) p block->frame + 587 == free_rec
$110 = true

Page header field PAGE_FREE holds 587 offset and this is where we get free record with heap_no 23.

6. thread 1: undo is continued

#0  btr_cur_update_in_place (flags=7, cursor=0x61a000196f78, offsets=0x6140000256c8, update=0x618000077908, cmpl_info=0, thr=0x6160020ebdc0, trx_id=89, mtr=0x7fd45b126f50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4358
#1  0x000055751f5f9f94 in btr_cur_optimistic_update (flags=7, cursor=0x61a000196f78, offsets=0x7fd45b126e70, heap=0x7fd45b126e50, update=0x618000077908, cmpl_info=0, thr=0x6160020ebdc0, trx_id=89, mtr=0x7fd45b126f50) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/btr/btr0cur.cc:4601
#2  0x000055751f85d485 in row_undo_mod_clust_low (node=0x61a000196f08, offsets=0x7fd45b126e70, offsets_heap=0x7fd45b126e50, heap=0x61900050ff80, rebuilt_old_pk=0x7fd45b126e90, sys=0x7fd45b127490 "\300t\022[\324\177", thr=0x6160020ebdc0, mtr=0x7fd45b126f50, mode=2) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:132
#3  0x000055751f85f0a1 in row_undo_mod_clust (node=0x61a000196f08, thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:301
#4  0x000055751f86656f in row_undo_mod (node=0x61a000196f08, thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0umod.cc:1408
#5  0x000055751f4a900e in row_undo (node=0x61a000196f08, thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:426
#6  0x000055751f4a94fd in row_undo_step (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/row/row0undo.cc:478
#7  0x000055751f351b42 in que_thr_step (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:651
#8  0x000055751f351f06 in que_run_threads_low (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:709
#9  0x000055751f3520a8 in que_run_threads (thr=0x6160020ebdc0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/que/que0que.cc:729
#10 0x000055751f544ecb in trx_t::rollback_low (this=0x7eb201405b48, savept=0x0) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:125
#11 0x000055751f53f772 in trx_rollback_for_mysql_low (trx=0x7eb201405b48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:190
#12 0x000055751f53fd84 in trx_rollback_for_mysql (trx=0x7eb201405b48) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/trx/trx0roll.cc:221
#13 0x000055751f090278 in innobase_rollback (hton=0x615000002b18, thd=0x62b0000cb218, rollback_trx=false) at /data/Server/bb-10.6-midenok-MDEV-18706/storage/innobase/handler/ha_innodb.cc:4563
#14 0x000055751e7a90e0 in ha_rollback_trans (thd=0x62b0000cb218, all=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/handler.cc:2153
#15 0x000055751e408f68 in trans_rollback_stmt (thd=0x62b0000cb218) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/transaction.cc:535
#16 0x000055751dfed7ed in mysql_execute_command (thd=0x62b0000cb218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:6046
#17 0x000055751dff94a2 in mysql_parse (thd=0x62b0000cb218, rawbuf=0x62b0000d2238 "INSERT INTO t1 (a) VALUES ( 1), ( 1) /* E_R Thread1 QNO 14 CON_ID 14 */", length=71, parser_state=0x7fd45b128b20) at /data/Server/bb-10.6-midenok-MDEV-18706/sql/sql_parse.cc:8026

midenok commented 3 years ago

Info: gap locks problem

Gap locks without INSERT_INTENTION are read-gap-locks, they don't conflict each other:

    if ((lock_is_on_supremum || (type_mode & LOCK_GAP))
        && !(type_mode & LOCK_INSERT_INTENTION)) {

        /* Gap type locks without LOCK_INSERT_INTENTION flag
        do not need to wait for anything. This is because
        different users can have conflicting lock types
        on gaps. */

        return false;
    }

    if (!(type_mode & LOCK_INSERT_INTENTION) && lock2->is_gap()) {

        /* Record lock (LOCK_ORDINARY or LOCK_REC_NOT_GAP
        does not need to wait for a gap type lock */

        return false;
    }

    if ((type_mode & LOCK_GAP) && lock2->is_record_not_gap()) {

        /* Lock on gap does not need to wait for
        a LOCK_REC_NOT_GAP type lock */

        return false;
    }

    if (lock2->is_insert_intention()) {
        /* No lock request needs to wait for an insert
        intention lock to be removed. This is ok since our
        rules allow conflicting locks on gaps. This eliminates
        a spurious deadlock caused by a next-key lock waiting
        for an insert intention lock; when the insert
        intention lock was granted, the insert deadlocked on
        the waiting next-key lock.

        Also, insert intention locks do not disturb each
        other. */

        return false;
    }

https://jira.mariadb.org/browse/MDEV-20605?focusedCommentId=135881&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-135881

midenok commented 3 years ago

Good

CURRENT_TEST: innodb.v
2021-07-26 10:30:32 0 [Warning] InnoDB: Linux Native AIO disabled.
que_eval_sql: exit: ADD(0x7fe8c70ffd28) [trx=0x7fe8c70ff1d8 (1:0), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
que_eval_sql: ib_lock: ADD(0x7fe8c70ff268) [trx=0x7fe8c70ff1d8 (1:1), type_mode=3=X, heap_no=2 [space=0, page_no=11, n_bits=16]]
innodb_init: exit: DEL(0x7fe8c70ffd28) [trx=0x7fe8c70ff1d8 (0:1), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
2021-07-26 10:30:32 0 [Warning] /home/midenok/src/mariadb/10.6b/build/sql/mysqld: unknown option '--loose-pam-debug'
2021-07-26 10:30:32 0 [Warning] /home/midenok/src/mariadb/10.6b/build/sql/mysqld: unknown option '--loose-aria'
2021-07-26 10:30:33 0 [Note] /home/midenok/src/mariadb/10.6b/build/sql/mysqld: ready for connections.
Version: '10.6.3-MariaDB-debug-log'  socket: '/home/midenok/src/mariadb/10.6b/build/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
create_table_def: exit: ADD(0x7fe8c7100ed0) [trx=0x7fe8c7100380 (1:0), type_mode=9=TABLE|IX [name=`SYS_TABLES`]]
create_table_def: exit: ADD(0x7fe8c7100f28) [trx=0x7fe8c7100380 (2:1), type_mode=9=TABLE|IX [name=`SYS_COLUMNS`]]
create_index: exit: ADD(0x7fe8c7100f80) [trx=0x7fe8c7100380 (3:2), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
create_index: exit: ADD(0x7fe8c7100fd8) [trx=0x7fe8c7100380 (4:3), type_mode=9=TABLE|IX [name=`SYS_FIELDS`]]
ha_innobase::create: exit: DEL(0x7fe8c7100fd8) [trx=0x7fe8c7100380 (3:4), type_mode=9=TABLE|IX [name=`SYS_FIELDS`]]
ha_innobase::create: exit: DEL(0x7fe8c7100f80) [trx=0x7fe8c7100380 (2:4), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
ha_innobase::create: exit: DEL(0x7fe8c7100f28) [trx=0x7fe8c7100380 (1:4), type_mode=9=TABLE|IX [name=`SYS_COLUMNS`]]
ha_innobase::create: exit: DEL(0x7fe8c7100ed0) [trx=0x7fe8c7100380 (0:4), type_mode=9=TABLE|IX [name=`SYS_TABLES`]]
ha_innobase::write_row: exit: ADD(0x7fe8c70ffd28) [trx=0x7fe8c70ff1d8 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
innobase_commit_ordered_2: exit: DEL(0x7fe8c70ffd28) [trx=0x7fe8c70ff1d8 (0:1), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_search_mvcc: exit: ADD(0x7fe8c70ffd28) [trx=0x7fe8c70ff1d8 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_search_mvcc: ib_lock: ADD(0x7fe8c70ff268) [trx=0x7fe8c70ff1d8 (1:1), type_mode=3=X, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_upd: ib_lock: WEAKER(X|REC_NOT_GAP, 0x7fe8c70ff268) [trx=0x7fe8c70ff1d8 (2:1), type_mode=3=X, heap_no=2 [space=5, page_no=3, n_bits=8]] 
innobase_commit_ordered_2: exit: DEL(0x7fe8c70ffd28) [trx=0x7fe8c70ff1d8 (0:1), type_mode=9=TABLE|IX [name=`test`.`t1`]]
ha_innobase::write_row: exit: ADD(0x7fe8c7102078) [trx=0x7fe8c7101528 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_ins_clust_index_entry_low: ib_lock: ADD(0x7fe8c71015b8) [trx=0x7fe8c7101528 (1:1), type_mode=1026=S|REC_NOT_GAP, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: ib_lock: NO_CONFLICTS(trx=0x7fe8c7101528, X|REC_NOT_GAP, 0) 
ha_innobase::write_row: exit: ADD(0x7fe8c7103220) [trx=0x7fe8c71026d0 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_ins_clust_index_entry_low: ib_lock: NO_CONFLICTS(trx=0x7fe8c71026d0, S|REC_NOT_GAP, 0) 
row_ins_clust_index_entry_low: ib_lock: ADD(0x7fe8c7102760) [trx=0x7fe8c71026d0 (1:1), type_mode=1026=S|REC_NOT_GAP, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: ib_lock: CONFLICTS(trx=0x7fe8c71026d0, X|REC_NOT_GAP, 0x7fe8c71015b8) [trx=0x7fe8c7101528 (2:1), type_mode=1026=S|REC_NOT_GAP, heap_no=2 [space=5, page_no=3, n_bits=8]] 
row_ins_clust_index_entry_low: ib_lock: ADD(0x7fe8c71028b8) [trx=0x7fe8c71026d0 (2:1), type_mode=1283=X|REC_NOT_GAP|WAIT, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: exit: trx 0x18 waits for lock in index `PRIMARY` of table `test`.`t1`
?func: ib_lock: ADD(0x7fe8c7101710) [trx=0x7fe8c7101528 (2:1), type_mode=514=S|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]
?func: ib_lock: ADD(0x7fe8c7102a10) [trx=0x7fe8c71026d0 (3:1), type_mode=514=S|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]
?func: ib_lock: ADD(0x7fe8c7102b68) [trx=0x7fe8c71026d0 (4:1), type_mode=515=X|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]
?func: ib_lock: -WAIT(0x7fe8c71028b8) [trx=0x7fe8c71026d0 (5:1), type_mode=1027=X|REC_NOT_GAP [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: ib_lock: CONFLICTS(trx=0x7fe8c71026d0, X|GAP|INSERT_INTENTION, 0x7fe8c7101710) [trx=0x7fe8c7101528 (3:1), type_mode=514=S|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]

Bad

CURRENT_TEST: innodb.v
2021-07-26 10:13:00 0 [Warning] InnoDB: Linux Native AIO disabled.
que_eval_sql: exit: ADD(0x7f98b73ffd28) [trx=0x7f98b73ff1d8 (1:0), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
que_eval_sql: ib_lock: ADD(0x7f98b73ff268) [trx=0x7f98b73ff1d8 (1:1), type_mode=3=X, heap_no=2 [space=0, page_no=11, n_bits=16]]
innodb_init: exit: DEL(0x7f98b73ffd28) [trx=0x7f98b73ff1d8 (0:1), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
2021-07-26 10:13:00 0 [Warning] /home/midenok/src/mariadb/10.6/build/sql/mysqld: unknown option '--loose-pam-debug'
2021-07-26 10:13:00 0 [Warning] /home/midenok/src/mariadb/10.6/build/sql/mysqld: unknown option '--loose-aria'
2021-07-26 10:13:01 0 [Note] /home/midenok/src/mariadb/10.6/build/sql/mysqld: ready for connections.
Version: '10.6.3-MariaDB-debug-log'  socket: '/home/midenok/src/mariadb/10.6/build/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
create_table_def: exit: ADD(0x7f98b7400ed0) [trx=0x7f98b7400380 (1:0), type_mode=9=TABLE|IX [name=`SYS_TABLES`]]
create_table_def: exit: ADD(0x7f98b7400f28) [trx=0x7f98b7400380 (2:1), type_mode=9=TABLE|IX [name=`SYS_COLUMNS`]]
create_index: exit: ADD(0x7f98b7400f80) [trx=0x7f98b7400380 (3:2), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
create_index: exit: ADD(0x7f98b7400fd8) [trx=0x7f98b7400380 (4:3), type_mode=9=TABLE|IX [name=`SYS_FIELDS`]]
ha_innobase::create: exit: DEL(0x7f98b7400fd8) [trx=0x7f98b7400380 (3:4), type_mode=9=TABLE|IX [name=`SYS_FIELDS`]]
ha_innobase::create: exit: DEL(0x7f98b7400f80) [trx=0x7f98b7400380 (2:4), type_mode=9=TABLE|IX [name=`SYS_INDEXES`]]
ha_innobase::create: exit: DEL(0x7f98b7400f28) [trx=0x7f98b7400380 (1:4), type_mode=9=TABLE|IX [name=`SYS_COLUMNS`]]
ha_innobase::create: exit: DEL(0x7f98b7400ed0) [trx=0x7f98b7400380 (0:4), type_mode=9=TABLE|IX [name=`SYS_TABLES`]]
ha_innobase::write_row: exit: ADD(0x7f98b73ffd28) [trx=0x7f98b73ff1d8 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
innobase_commit_ordered_2: exit: DEL(0x7f98b73ffd28) [trx=0x7f98b73ff1d8 (0:1), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_search_mvcc: exit: ADD(0x7f98b73ffd28) [trx=0x7f98b73ff1d8 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_search_mvcc: ib_lock: ADD(0x7f98b73ff268) [trx=0x7f98b73ff1d8 (1:1), type_mode=3=X, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_upd: ib_lock: WEAKER(X|REC_NOT_GAP, 0x7f98b73ff268) [trx=0x7f98b73ff1d8 (2:1), type_mode=3=X, heap_no=2 [space=5, page_no=3, n_bits=8]] 
innobase_commit_ordered_2: exit: DEL(0x7f98b73ffd28) [trx=0x7f98b73ff1d8 (0:1), type_mode=9=TABLE|IX [name=`test`.`t1`]]
ha_innobase::write_row: exit: ADD(0x7f98b7402078) [trx=0x7f98b7401528 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_ins_clust_index_entry_low: ib_lock: ADD(0x7f98b74015b8) [trx=0x7f98b7401528 (1:1), type_mode=1026=S|REC_NOT_GAP, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: ib_lock: NO_CONFLICTS(trx=0x7f98b7401528, X|REC_NOT_GAP, 0) 
ha_innobase::write_row: exit: ADD(0x7f98b7403220) [trx=0x7f98b74026d0 (1:0), type_mode=9=TABLE|IX [name=`test`.`t1`]]
row_ins_clust_index_entry_low: ib_lock: NO_CONFLICTS(trx=0x7f98b74026d0, S|REC_NOT_GAP, 0) 
row_ins_clust_index_entry_low: ib_lock: ADD(0x7f98b7402760) [trx=0x7f98b74026d0 (1:1), type_mode=1026=S|REC_NOT_GAP, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: ib_lock: CONFLICTS(trx=0x7f98b74026d0, X|REC_NOT_GAP, 0x7f98b74015b8) [trx=0x7f98b7401528 (2:1), type_mode=1026=S|REC_NOT_GAP, heap_no=2 [space=5, page_no=3, n_bits=8]] 
row_ins_clust_index_entry_low: ib_lock: ADD(0x7f98b74028b8) [trx=0x7f98b74026d0 (2:1), type_mode=1283=X|REC_NOT_GAP|WAIT, heap_no=2 [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: exit: trx 0x18 waits for lock in index `PRIMARY` of table `test`.`t1`
?func: ib_lock: ADD(0x7f98b7401710) [trx=0x7f98b7401528 (2:1), type_mode=514=S|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]
?func: ib_lock: ADD(0x7f98b7402a10) [trx=0x7f98b74026d0 (3:1), type_mode=514=S|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]
?func: ib_lock: ADD(0x7f98b7402b68) [trx=0x7f98b74026d0 (4:1), type_mode=515=X|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]
?func: ib_lock: -WAIT(0x7f98b74028b8) [trx=0x7f98b74026d0 (5:1), type_mode=1027=X|REC_NOT_GAP [space=5, page_no=3, n_bits=8]]
row_ins_clust_index_entry_low: ib_lock: NO_CONFLICTS(trx=0x7f98b74026d0, X|GAP|INSERT_INTENTION, 0) because: WEAKER(X|GAP|INSERT_INTENTION, 0x7f98b7402b68) [trx=0x7f98b74026d0 (5:1), type_mode=515=X|GAP, heap_no=3 [space=5, page_no=3, n_bits=8]]

Cause

New lock X|GAP|INSERT_INTENTION is considered weaker than X|GAP. That is wrong because GAP without INSERT_INTENTION doesn't wait anything (see previous comment), i.e. that is the weakest lock.

Fix candidate

--- a/storage/innobase/include/lock0priv.h
+++ b/storage/innobase/include/lock0priv.h
@@ -586,11 +586,12 @@ bool ib_lock_t::is_stronger(ulint precise_mode, ulint heap_no, const trx_t* t) c
            && !is_waiting()
            && !is_insert_intention()
            && (!is_record_not_gap()
-               || (precise_mode & LOCK_REC_NOT_GAP) /* only record */
-               || heap_no == PAGE_HEAP_NO_SUPREMUM)
+               || heap_no == PAGE_HEAP_NO_SUPREMUM
+               || (precise_mode & LOCK_REC_NOT_GAP)) /* only record */
            && (!is_gap()
-               || (precise_mode & LOCK_GAP)         /* only gap */
-               || heap_no == PAGE_HEAP_NO_SUPREMUM)
+               || heap_no == PAGE_HEAP_NO_SUPREMUM
+               || ((precise_mode & LOCK_GAP) &&  /* only gap */
+                    !(precise_mode & LOCK_INSERT_INTENTION)))
            && lock_mode_stronger_or_eq(
                mode(),
                static_cast<lock_mode>(

midenok commented 1 year ago

Reproduce

# MDEV-22698 Deadlock on concurrent acquisition of multiple indexes
--source include/have_innodb.inc
create table t1 (a int unique) engine innodb;
insert into t1 values (1);
connect (con1, localhost, root,, test);
#set debug_sync= 'lock_trx_handle_wait_enter signal first_ins_locked';
send delete from t1;
connection default;
#set debug_sync= 'lock_wait_start wait_for first_ins_locked';
--error ER_LOCK_DEADLOCK
delete from t1 where a = 1;
show engine innodb status;
connection con1;
reap;
connection default;
disconnect con1;
drop table t1;

1. First lock

#0  lock_rec_lock (impl=false, mode=1027, block=0x7f24c6c00cb0, heap_no=2, index=0x7f24a004ce98, thr=0x7f24a00595f8) at ../src/storage/innobase/lock/lock0lock.cc:1486
#1  0x000055f4c3ada48e in lock_sec_rec_read_check_and_lock (flags=0, block=0x7f24c6c00cb0, rec=0x7f24c6ce007e "\200", index=0x7f24a004ce98, offsets=0x7f24c40eba60, mode=LOCK_X, gap_mode=1024, thr=0x7f24a00595f8) at ../src/storage/innobase/lock/lock0lock.cc:5537
#2  0x000055f4c3c3d321 in sel_set_rec_lock (pcur=0x7f24a0058e98, rec=0x7f24c6ce007e "\200", index=0x7f24a004ce98, offsets=0x7f24c40eba60, mode=3, type=1024, thr=0x7f24a00595f8, mtr=0x7f24c40ebcc0) at ../src/storage/innobase/row/row0sel.cc:1369
#3  0x000055f4c3c388ff in row_search_mvcc (buf=0x7f24a0055028 "\377", mode=PAGE_CUR_GE, prebuilt=0x7f24a0058cc8, match_mode=1, direction=0) at ../src/storage/innobase/row/row0sel.cc:5228
#4  0x000055f4c384b53f in ha_innobase::index_read (this=0x7f24a00506a0, buf=0x7f24a0055028 "\377", key_ptr=0x7f24a0963b70 "", key_len=5, find_flag=HA_READ_KEY_EXACT) at ../src/storage/innobase/handler/ha_innodb.cc:8986
#5  0x000055f4c2f78dca in handler::index_read_map (this=0x7f24a00506a0, buf=0x7f24a0055028 "\377", key=0x7f24a0963b70 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at ../src/sql/handler.h:3925
#6  0x000055f4c2f61fe0 in handler::ha_index_read_map (this=0x7f24a00506a0, buf=0x7f24a0055028 "\377", key=0x7f24a0963b70 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at ../src/sql/handler.cc:3471
#7  0x000055f4c2f6d19b in handler::read_range_first (this=0x7f24a00506a0, start_key=0x7f24a00507a0, end_key=0x7f24a00507c0, eq_range_arg=true, sorted=true) at ../src/sql/handler.cc:6539
#8  0x000055f4c35957b2 in handler::multi_range_read_next (this=0x7f24a00506a0, range_info=0x7f24c40ec488) at ../src/sql/multi_range_read.cc:518
#9  0x000055f4c3595949 in Mrr_simple_index_reader::get_next (this=0x7f24a0050cd8, range_info=0x7f24c40ec488) at ../src/sql/multi_range_read.cc:555
#10 0x000055f4c3598a3a in DsMrr_impl::dsmrr_next (this=0x7f24a0050b88, range_info=0x7f24c40ec488) at ../src/sql/multi_range_read.cc:1655
#11 0x000055f4c3863094 in ha_innobase::multi_range_read_next (this=0x7f24a00506a0, range_info=0x7f24c40ec488) at ../src/storage/innobase/handler/ha_innodb.cc:20012
#12 0x000055f4c30c0057 in QUICK_RANGE_SELECT::get_next (this=0x7f24a0022ec0) at ../src/sql/opt_range.cc:12727
#13 0x000055f4c30e7ded in rr_quick (info=0x7f24c40ed0b0) at ../src/sql/records.cc:403
#14 0x000055f4c30d20a6 in READ_RECORD::read_record (this=0x7f24c40ed0b0) at ../src/sql/records.h:81
#15 0x000055f4c3296335 in mysql_delete (thd=0x7f24a00020f8, table_list=0x7f24a002df70, conds=0x7f24a002e830, order_list=0x7f24a0007030, limit=18446744073709551615, options=0, result=0x0) at ../src/sql/sql_delete.cc:812
#16 0x000055f4c330ab63 in mysql_execute_command (thd=0x7f24a00020f8, is_called_from_prepared_stmt=false) at ../src/sql/sql_parse.cc:4812
#17 0x000055f4c330027f in mysql_parse (thd=0x7f24a00020f8, rawbuf=0x7f24a002de90 "delete from t1 where a = 1", length=26, parser_state=0x7f24c40ef288) at ../src/sql/sql_parse.cc:8005

2. Second lock

#0  lock_rec_lock (impl=false, mode=1027, block=0x7f24c6c00be0, heap_no=2, index=0x7f24a0057e88, thr=0x7f24a00595f8) at ../src/storage/innobase/lock/lock0lock.cc:1486
#1  0x000055f4c3adab00 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7f24c6c00be0, rec=0x7f24c6cdc07e "", index=0x7f24a0057e88, offsets=0x7f24c40eba60, mode=LOCK_X, gap_mode=1024, thr=0x7f24a00595f8) at ../src/storage/innobase/lock/lock0lock.cc:5607
#2  0x000055f4c3c33a0a in Row_sel_get_clust_rec_for_mysql::operator() (this=0x7f24c40ebf98, prebuilt=0x7f24a0058cc8, sec_index=0x7f24a004ce98, rec=0x7f24c6ce007e "\200", thr=0x7f24a00595f8, out_rec=0x7f24c40ebfb8, offsets=0x7f24c40eba58, offset_heap=0x7f24c40ebcb8, vrow=0x0, mtr=0x7f24c40ebcc0) at ../src/storage/innobase/row/row0sel.cc:3497
#3  0x000055f4c3c39956 in row_search_mvcc (buf=0x7f24a0055028 "\377", mode=PAGE_CUR_GE, prebuilt=0x7f24a0058cc8, match_mode=1, direction=0) at ../src/storage/innobase/row/row0sel.cc:5503
#4  0x000055f4c384b53f in ha_innobase::index_read (this=0x7f24a00506a0, buf=0x7f24a0055028 "\377", key_ptr=0x7f24a0963b70 "", key_len=5, find_flag=HA_READ_KEY_EXACT) at ../src/storage/innobase/handler/ha_innodb.cc:8986
#5  0x000055f4c2f78dca in handler::index_read_map (this=0x7f24a00506a0, buf=0x7f24a0055028 "\377", key=0x7f24a0963b70 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at ../src/sql/handler.h:3925
#6  0x000055f4c2f61fe0 in handler::ha_index_read_map (this=0x7f24a00506a0, buf=0x7f24a0055028 "\377", key=0x7f24a0963b70 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at ../src/sql/handler.cc:3471
#7  0x000055f4c2f6d19b in handler::read_range_first (this=0x7f24a00506a0, start_key=0x7f24a00507a0, end_key=0x7f24a00507c0, eq_range_arg=true, sorted=true) at ../src/sql/handler.cc:6539
#8  0x000055f4c35957b2 in handler::multi_range_read_next (this=0x7f24a00506a0, range_info=0x7f24c40ec488) at ../src/sql/multi_range_read.cc:518
#9  0x000055f4c3595949 in Mrr_simple_index_reader::get_next (this=0x7f24a0050cd8, range_info=0x7f24c40ec488) at ../src/sql/multi_range_read.cc:555
#10 0x000055f4c3598a3a in DsMrr_impl::dsmrr_next (this=0x7f24a0050b88, range_info=0x7f24c40ec488) at ../src/sql/multi_range_read.cc:1655
#11 0x000055f4c3863094 in ha_innobase::multi_range_read_next (this=0x7f24a00506a0, range_info=0x7f24c40ec488) at ../src/storage/innobase/handler/ha_innodb.cc:20012
#12 0x000055f4c30c0057 in QUICK_RANGE_SELECT::get_next (this=0x7f24a0022ec0) at ../src/sql/opt_range.cc:12727
#13 0x000055f4c30e7ded in rr_quick (info=0x7f24c40ed0b0) at ../src/sql/records.cc:403
#14 0x000055f4c30d20a6 in READ_RECORD::read_record (this=0x7f24c40ed0b0) at ../src/sql/records.h:81
#15 0x000055f4c3296335 in mysql_delete (thd=0x7f24a00020f8, table_list=0x7f24a002df70, conds=0x7f24a002e830, order_list=0x7f24a0007030, limit=18446744073709551615, options=0, result=0x0) at ../src/sql/sql_delete.cc:812
#16 0x000055f4c330ab63 in mysql_execute_command (thd=0x7f24a00020f8, is_called_from_prepared_stmt=false) at ../src/sql/sql_parse.cc:4812
#17 0x000055f4c330027f in mysql_parse (thd=0x7f24a00020f8, rawbuf=0x7f24a002de90 "delete from t1 where a = 1", length=26, parser_state=0x7f24c40ef288) at ../src/sql/sql_parse.cc:8005

midenok / mariadb

MDEV-18706 ER_LOCK_DEADLOCK on concurrent read and insert into already locked gap #56

Reproduce

Result

Links

On HANDLER

Deadlock possibilities

Tips

Bad

Transaction 1

frame 7

frame 9

Transaction 2

frame 4

frame 7

frame 10

Good: INSERT

1. IX lock acquired

2. IX lock freed

Good: UPDATE

1. IX lock acquired

2. Rec lock

3. Rec lock

4. Rec lock

5. Rec lock

6. Rec lock

7. Locks released

Info

Calls of interest

Info: debug IB

rec_printer() example

Locks instrumentation

Bad

1. Deadlock detected

2. Transaction set victim

frame 2

Info: on heap number (13 bits)

Bad: DeadlockChecker::search() iterations (T2)

T1

T2

frame 4 (T2: update t1 set c= 4)

thread 28 frame 17 (T1: handler h read primary prev)

1. T2-II-W vs T2-X: no conflict, getting next lock

2. T2-II-W vs T1-S-W: conflict, pushing state

3. T1-S-W vs T2-X: conflict, found cycle

Good

Cause

Calls of interest

Fix

Bug 1: innodb.auto_increment_dup,log-bin fails

Result

Reproduce

Cause

Bug 2: versioning.update fails

Result

Reproduce

Cause

TODO

Bug 3: SELECT FOR UPDATE doesn't display inserted record

Reproduce

Result

Expected

Good

1. SELECT locks the record

frame 1

2. SELECT waits for X lock

Good 2

T1

T2

T1

Cause

Expected

for (2)

for (3)

Position is stored

frame 1

Fix

Bug 4: deadlock on implicit locking

Reproduce

1. Explicit lock skipped

thread 28 frame 17 (T1: handler h read `primary` prev)

Bug 1: `innodb.auto_increment_dup,log-bin` fails

Bug 2: `versioning.update` fails