[MDEV-25487] Assertion `!lock_sys_t::get_first(receiver_cell, receiver_id, receiver_heap_no)' failed in lock_rec_move Created: 2021-04-22  Updated: 2021-04-23  Resolved: 2021-04-23

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

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: not-10.2, not-10.3, not-10.4, not-10.5, regression

Issue Links:
Problem/Incident
is caused by MDEV-515 innodb bulk insert Closed
Relates
relates to MDEV-24914 Assertion `lock_rec_get_first( lock_h... Closed
relates to MDEV-25315 Assertion `ptr' failed in ut_align_do... Closed
relates to MDEV-25010 Assertion `!lock_sys_t::get_first(rec... Closed

 Description   

Possibly related to MDEV-25010, though that bug does not reproduce for me. Also see MDEV-24914.

CREATE TABLE t1 (a INT KEY, b TEXT) ENGINE=InnoDB;
XA START 'a';
SET unique_checks=0,foreign_key_checks=0,@@GLOBAL.innodb_limit_optimistic_insert_debug=2;
UPDATE t1 SET b=1;
CREATE TEMPORARY TABLE t2 (a INT, b INT) ENGINE=InnoDB;
INSERT INTO t1 VALUES (0,0),(1,1),(2,2);
INSERT INTO t2 VALUES (0);
INSERT INTO t1 VALUES (2,2),(3,3);
INSERT INTO t1 VALUES (4,4);

Leads to:

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Debug)

mysqld: /test/10.6_dbg/storage/innobase/lock/lock0lock.cc:2140: void lock_rec_move(hash_cell_t&, const buf_block_t&, page_id_t, const hash_cell_t&, page_id_t, ulint, ulint): Assertion `!lock_sys_t::get_first(receiver_cell, receiver_id, receiver_heap_no)' failed.

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Debug)

Core was generated by `/test/MD150421-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x1522d8099700 (LWP 2140814))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00001522daa56859 in __GI_abort () at abort.c:79
#2  0x00001522daa56729 in __assert_fail_base (fmt=0x1522dabec588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55d07673f310 "!lock_sys_t::get_first(receiver_cell, receiver_id, receiver_heap_no)", file=0x55d07673d4d0 "/test/10.6_dbg/storage/innobase/lock/lock0lock.cc", line=2140, function=<optimized out>) at assert.c:92
#3  0x00001522daa67f36 in __GI___assert_fail (assertion=assertion@entry=0x55d07673f310 "!lock_sys_t::get_first(receiver_cell, receiver_id, receiver_heap_no)", file=file@entry=0x55d07673d4d0 "/test/10.6_dbg/storage/innobase/lock/lock0lock.cc", line=line@entry=2140, function=function@entry=0x55d07673f358 "void lock_rec_move(hash_cell_t&, const buf_block_t&, page_id_t, const hash_cell_t&, page_id_t, ulint, ulint)") at assert.c:101
#4  0x000055d075f9fb67 in lock_rec_move (receiver_cell=@0x55d077c8fd58: {node = 0x1522d81524a8}, receiver=@0x1522b8010f40: {page = {id_ = {m_id = 21474836485}, buf_fix_count_ = {m_counter = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 1}, <No data fields>}}, io_fix_ = {m = {static _S_min_alignment = 4, static _S_alignment = 4, _M_i = BUF_IO_NONE}}, state_ = BUF_BLOCK_FILE_PAGE, hash = 0x0, zip = {data = 0x0, m_start = 0, m_external = false, m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 0}, slot = 0x0, in_zip_hash = false, in_LRU_list = true, in_page_hash = true, in_free_list = false, list = {prev = 0x1522b8010e60, next = 0x1522b80010a0}, oldest_modification_ = {m_counter = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 45092}, <No data fields>}}, LRU = {prev = 0x1522b8011020, next = 0x1522b8010e60}, old = 0, freed_page_clock = 0, access_time = {m_counter = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 1669121218}, <No data fields>}}, ibuf_exist = false, status = buf_page_t::INIT_ON_FLUSH}, frame = 0x1522b8694000 "", lock = {lock = {<rw_lock> = {lock = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 2147483648}, <No data fields>}, static UNLOCKED = 0, static WRITER = 2147483648, static WRITER_WAITING = 1073741824, static WRITER_PENDING = 3221225472, static UPDATER = 536870912}, <No data fields>}, recursive = 1, writer = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 23239397578496}, <No data fields>}, static FOR_IO = 18446744073709551615, readers_lock = {<rw_lock> = {lock = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 0}, <No data fields>}, static UNLOCKED = 0, static WRITER = 2147483648, static WRITER_WAITING = 1073741824, static WRITER_PENDING = 3221225472, static UPDATER = 536870912}, <No data fields>}, readers = {_M_b = {_M_p = 0x1522ac0028d0}}, static RECURSIVE_X = 1, static RECURSIVE_U = 65536, static RECURSIVE_MAX = 65535}, in_withdraw_list = false, in_unzip_LRU_list = false, unzip_LRU = {prev = 0x0, next = 0x0}, modify_clock = 2, n_bytes = 0, n_fields = 1, n_hash_helps = 0, left_side = true, n_pointers = {m_counter = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 0}, <No data fields>}}, curr_n_fields = 0, curr_n_bytes = 0, curr_left_side = 0, index = 0x0}, receiver_id=<optimized out>, receiver_id@entry={m_id = 21474836485}, donator_cell=@0x55d077c8fd60: {node = 0x1522d8152350}, donator_id=<optimized out>, donator_id@entry={m_id = 21474836484}, receiver_heap_no=receiver_heap_no@entry=1, donator_heap_no=1) at /test/10.6_dbg/storage/innobase/lock/lock0lock.cc:2140
#5  0x000055d075fa061f in lock_update_split_right (right_block=right_block@entry=0x1522b8010f40, left_block=left_block@entry=0x1522b8010e60) at /test/10.6_dbg/storage/innobase/include/lock0lock.h:938
#6  0x000055d07616d6bd in btr_page_split_and_insert (flags=flags@entry=0, cursor=cursor@entry=0x1522d80966c0, offsets=offsets@entry=0x1522d8096688, heap=heap@entry=0x1522d8096680, tuple=tuple@entry=0x15228c0210a8, n_ext=n_ext@entry=0, mtr=0x1522d8096c70) at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:3057
#7  0x000055d07616ea11 in btr_root_raise_and_insert (flags=flags@entry=0, cursor=cursor@entry=0x1522d80966c0, offsets=offsets@entry=0x1522d8096688, heap=heap@entry=0x1522d8096680, tuple=tuple@entry=0x15228c0210a8, n_ext=0, mtr=0x1522d8096c70) at /test/10.6_dbg/storage/innobase/btr/btr0btr.cc:2068
#8  0x000055d0761888b6 in btr_cur_pessimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x1522d80966c0, offsets=offsets@entry=0x1522d8096688, heap=heap@entry=0x1522d8096680, entry=entry@entry=0x15228c0210a8, rec=rec@entry=0x1522d8096698, big_rec=0x1522d8096678, n_ext=<optimized out>, thr=0x15228c030a78, mtr=0x1522d8096c70) at /test/10.6_dbg/storage/innobase/btr/btr0cur.cc:3771
#9  0x000055d076065789 in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=33, index=index@entry=0x15228c021a78, n_uniq=n_uniq@entry=1, entry=entry@entry=0x15228c0210a8, n_ext=n_ext@entry=0, thr=<optimized out>) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:2809
#10 0x000055d076066460 in row_ins_clust_index_entry (index=index@entry=0x15228c021a78, entry=entry@entry=0x15228c0210a8, thr=thr@entry=0x15228c030a78, n_ext=n_ext@entry=0) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3280
#11 0x000055d07606af0a in row_ins_index_entry (thr=0x15228c030a78, entry=0x15228c0210a8, index=0x15228c021a78) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3388
#12 row_ins_index_entry_step (thr=0x15228c030a78, node=0x15228c030840) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3557
#13 row_ins (thr=0x15228c030a78, node=0x15228c030840) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3703
#14 row_ins_step (thr=thr@entry=0x15228c030a78) at /test/10.6_dbg/storage/innobase/row/row0ins.cc:3845
#15 0x000055d07608f8e0 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x15228c02f418 "\376\004", prebuilt=0x15228c0300d8, ins_mode=ROW_INS_NORMAL) at /test/10.6_dbg/storage/innobase/row/row0mysql.cc:1395
#16 0x000055d075f1573a in ha_innobase::write_row (this=0x15228c02f880, record=0x15228c02f418 "\376\004") at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:7424
#17 0x000055d075b20f0d in handler::ha_write_row (this=0x15228c02f880, buf=0x15228c02f418 "\376\004") at /test/10.6_dbg/sql/handler.cc:7156
#18 0x000055d0757fabfd in write_record (thd=thd@entry=0x15228c000db8, table=table@entry=0x15228c02ef88, info=info@entry=0x1522d8097d00, sink=sink@entry=0x0) at /test/10.6_dbg/sql/sql_insert.cc:2106
#19 0x000055d075806474 in mysql_insert (thd=thd@entry=0x15228c000db8, table_list=0x15228c013c90, fields=@0x15228c005e60: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x55d076e1c280 <end_of_list>, last = 0x15228c005e60, elements = 0}, <No data fields>}, values_list=@0x15228c005ea8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x15228c014970, last = 0x15228c014970, elements = 1}, <No data fields>}, update_fields=@0x15228c005e90: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x55d076e1c280 <end_of_list>, last = 0x15228c005e90, elements = 0}, <No data fields>}, update_values=@0x15228c005e78: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x55d076e1c280 <end_of_list>, last = 0x15228c005e78, elements = 0}, <No data fields>}, duplic=DUP_ERROR, ignore=false, result=0x0) at /test/10.6_dbg/sql/sql_insert.cc:1099
#20 0x000055d07584d1ac in mysql_execute_command (thd=thd@entry=0x15228c000db8) at /test/10.6_dbg/sql/sql_parse.cc:4559
#21 0x000055d075837a06 in mysql_parse (thd=thd@entry=0x15228c000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1522d8098410) at /test/10.6_dbg/sql/sql_parse.cc:8017
#22 0x000055d0758467df in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x15228c000db8, packet=packet@entry=0x15228c00b369 "INSERT INTO t1 VALUES (4,4)", packet_length=packet_length@entry=27, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1331
#23 0x000055d075849bd5 in do_command (thd=0x15228c000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1406
#24 0x000055d0759a377c in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55d077fc73b8, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#25 0x000055d0759a3d81 in handle_one_connection (arg=arg@entry=0x55d077fc73b8) at /test/10.6_dbg/sql/sql_connect.cc:1312
#26 0x000055d075e51a03 in pfs_spawn_thread (arg=0x55d077eeba88) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#27 0x00001522daf64609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#28 0x00001522dab53293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt), 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (dbg), 10.4.19 (opt), 10.5.10 (dbg), 10.5.10 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)

On optimized:

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Optimized)

10.6.0-opt>INSERT INTO t2 VALUES (0);
ERROR 1136 (21S01): Column count doesn't match value count at row 1
10.6.0-opt>INSERT INTO t1 VALUES (2,2),(3,3);
ERROR 1062 (23000): Duplicate entry '2' for key 'PRIMARY'
10.6.0-opt>INSERT INTO t1 VALUES (4,4);
Query OK, 1 row affected (0.000 sec)

10.5 (Debug) gives the same output as 10.6 (Optimized) above (thus a regression).



 Comments   
Comment by Sergei Golubchik [ 2021-04-22 ]

Another one of test cases that just mixes everything.
Could you please explain what the test case it about? Like "duplicate key violation in bulk insert mode".
Because currently it's hardly possible to see what's going on here and what the bug is about.

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

Here is a little simpler version of the test. Curiously, the ER_WRONG_VALUE_COUNT_ON_ROW is needed:

--source include/have_innodb.inc
--source include/have_debug.inc
 
CREATE TABLE t1 (a INT KEY) ENGINE=InnoDB;
 
SET unique_checks=0,foreign_key_checks=0;
SET @save_limit = @@GLOBAL.innodb_limit_optimistic_insert_debug;
SET GLOBAL innodb_limit_optimistic_insert_debug = 2;
 
BEGIN;
SELECT * FROM t1 LOCK IN SHARE MODE;
INSERT INTO t1 VALUES (0),(1),(2);
--error ER_WRONG_VALUE_COUNT_ON_ROW
INSERT INTO t1 VALUES (0,1);
INSERT INTO t1 VALUES (2),(3),(4);
 
SET GLOBAL innodb_limit_optimistic_insert_debug = @save_limit;
DROP TABLE t1;

The InnoDB assertion fails because explicit locks had been acquired for index records in the table. I think that we must prohibit bulk insert if explicit record locks exist. Because we use table-level locking and undo logging for MDEV-515 (extended by MDEV-24818), we are not prepared to deal with record locks.

I did not debug why the ER_WRONG_VALUE_COUNT_ON_ROW is needed in the middle, and I do not need to know it in order to fix the InnoDB bug.

Comment by Roel Van de Paar [ 2021-04-23 ]

It is very helpful to know that one may be able to remove XA altogether by using a trx (BEGIN) instead. Thank you marko

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

This failure is easiest to avoid by refusing to enable bulk insert if record locks on the table exist. The intended usage scenario of MDEV-515 and MDEV-24818 is an INSERT-only transaction.

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