Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.3(EOL), 10.4(EOL), 10.5
Description
Notes:
- Given the history of false-positives in attempts to reproduce
MDEV-14643/MDEV-9663, I file this one separately. If we are lucky this time and turns out to be the problem that we have been chasing for withinMDEV-14643, feel free to close as a duplicate. - Due to system versioning in the scenario, the test case is not applicable to 10.2. I suspect that system versioning as such may be unrelated and only creates the right index structure under the hood, but I couldn't get rid of it. I expect if it is possible, it will become obvious during the development analysis.
- Please note that !cursor->index->is_committed() only happens on non-debug builds. Debug builds fail with a different assertion. Both are quoted below.
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 ( |
a int, |
b int, |
row_start bigint(20) unsigned GENERATED ALWAYS AS ROW START, |
row_end bigint(20) unsigned GENERATED ALWAYS AS ROW END, |
UNIQUE KEY (b,row_end), |
KEY (row_start), |
PERIOD FOR SYSTEM_TIME (row_start,row_end) |
) ENGINE=InnoDB WITH SYSTEM VERSIONING; |
|
|
INSERT INTO t1 (a,b) VALUES (1,2); |
REPLACE INTO t1 (a,b) VALUES (3,2),(3,2); |
|
|
# Cleanup
|
DROP TABLE t1; |
|
10.3 non-debug 0fb84216 |
2020-03-27 15:11:04 9 [ERROR] InnoDB: Record in index `row_start` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {[8] '(0x0000000000000027),[6] (0x000000000200)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8] $(0x0000000000000024),[6] (0x000000000202)}
|
2020-03-27 15:11:04 0x7f3ea039a700 InnoDB: Assertion failure in file /data/src/10.3/storage/innobase/row/row0ins.cc line 266
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
|
|
#5 0x00007f3ea6fd642a in __GI_abort () at abort.c:89
|
#6 0x0000556e50e1f885 in ut_dbg_assertion_failed (expr=expr@entry=0x556e5170f038 "!cursor->index->is_committed()", file=file@entry=0x556e5170eb50 "/data/src/10.3/storage/innobase/row/row0ins.cc", line=line@entry=266) at /data/src/10.3/storage/innobase/ut/ut0dbg.cc:60
|
#7 0x0000556e512bfa7b in row_ins_sec_index_entry_by_modify (mtr=0x7f3ea0396760, thr=0x7f3e58066ba8, entry=0x7f3e580a94f8, heap=0x7f3e580a9e20, offsets_heap=<optimized out>, offsets=0x7f3ea0395880, cursor=0x7f3ea0395950, mode=2, flags=0) at /data/src/10.3/storage/innobase/row/row0ins.cc:266
|
#8 row_ins_sec_index_entry_low (flags=flags@entry=0, mode=mode@entry=2, index=index@entry=0x7f3e58064258, offsets_heap=<optimized out>, offsets_heap@entry=0x7f3e580a99b0, heap=heap@entry=0x7f3e580a9e20, entry=entry@entry=0x7f3e580a94f8, trx_id=<optimized out>, thr=<optimized out>) at /data/src/10.3/storage/innobase/row/row0ins.cc:3118
|
#9 0x0000556e512bff59 in row_ins_sec_index_entry (index=index@entry=0x7f3e58064258, entry=0x7f3e580a94f8, thr=thr@entry=0x7f3e58066ba8, check_foreign=<optimized out>) at /data/src/10.3/storage/innobase/row/row0ins.cc:3315
|
#10 0x0000556e512f5df0 in row_upd_sec_index_entry (node=node@entry=0x7f3e58066850, thr=thr@entry=0x7f3e58066ba8) at /data/src/10.3/storage/innobase/row/row0upd.cc:2539
|
#11 0x0000556e512fb586 in row_upd_sec_step (thr=0x7f3e58066ba8, node=0x7f3e58066850) at /data/src/10.3/storage/innobase/row/row0upd.cc:2566
|
#12 row_upd (thr=0x7f3e58066ba8, node=0x7f3e58066850) at /data/src/10.3/storage/innobase/row/row0upd.cc:3336
|
#13 row_upd_step (thr=thr@entry=0x7f3e58066ba8) at /data/src/10.3/storage/innobase/row/row0upd.cc:3451
|
#14 0x0000556e512d052c in row_update_for_mysql (prebuilt=0x7f3e58065cf8) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1888
|
#15 0x0000556e51224c00 in ha_innobase::update_row (this=0x7f3e58070ed0, old_row=0x7f3e580648d8 "", new_row=0x7f3e580648b8 "\371\003") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:8838
|
#16 0x0000556e510bbc0b in handler::ha_update_row (this=0x7f3e58070ed0, old_data=0x7f3e580648d8 "", new_data=0x7f3e580648b8 "\371\003") at /data/src/10.3/sql/handler.cc:6479
|
#17 0x0000556e50ebcc84 in write_record (thd=thd@entry=0x7f3e580009a8, table=table@entry=0x7f3e580702f8, info=info@entry=0x7f3ea0397c60) at /data/src/10.3/sql/sql_insert.cc:1953
|
#18 0x0000556e50ec61c1 in mysql_insert (thd=thd@entry=0x7f3e580009a8, table_list=<optimized out>, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_REPLACE, ignore=false) at /data/src/10.3/sql/sql_insert.cc:1072
|
#19 0x0000556e50eebcb5 in mysql_execute_command (thd=thd@entry=0x7f3e580009a8) at /data/src/10.3/sql/sql_parse.cc:4454
|
#20 0x0000556e50ef04f9 in mysql_parse (thd=thd@entry=0x7f3e580009a8, rawbuf=<optimized out>, length=40, parser_state=parser_state@entry=0x7f3ea0399620, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.3/sql/sql_parse.cc:7817
|
#21 0x0000556e50ef2d0d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f3e580009a8, packet=packet@entry=0x7f3e580070c9 "REPLACE INTO t1 (a,b) VALUES (3,2),(3,2)", packet_length=packet_length@entry=40, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.3/sql/sql_parse.cc:1856
|
#22 0x0000556e50ef3986 in do_command (thd=0x7f3e580009a8) at /data/src/10.3/sql/sql_parse.cc:1401
|
#23 0x0000556e50fbadb4 in do_handle_one_connection (connect=connect@entry=0x556e530e95d8) at /data/src/10.3/sql/sql_connect.cc:1403
|
#24 0x0000556e50fbae64 in handle_one_connection (arg=arg@entry=0x556e530e95d8) at /data/src/10.3/sql/sql_connect.cc:1308
|
#25 0x0000556e51524744 in pfs_spawn_thread (arg=0x556e53085d98) at /data/src/10.3/storage/perfschema/pfs.cc:1869
|
#26 0x00007f3ea8f564a4 in start_thread (arg=0x7f3ea039a700) at pthread_create.c:456
|
#27 0x00007f3ea708ad0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
|
10.3 debug 0fb84216 |
2020-03-27 15:14:22 9 [ERROR] InnoDB: Record in index `row_start` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {[8] '(0x0000000000000027),[6] (0x000000000200)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8] $(0x0000000000000024),[6] (0x000000000202)}
|
mysqld: /data/src/10.3/storage/innobase/row/row0upd.cc:2442: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `btr_validate_index(index, 0, false)' failed.
|
200327 15:14:22 [ERROR] mysqld got signal 6 ;
|
|
|
#6 0x00007f3739274e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55a2928756d8 "btr_validate_index(index, 0, false)", file=file@entry=0x55a292875080 "/data/src/10.3/storage/innobase/row/row0upd.cc", line=line@entry=2442, function=function@entry=0x55a292877f40 <row_upd_sec_index_entry(upd_node_t*, que_thr_t*)::__PRETTY_FUNCTION__> "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:92
|
#7 0x00007f3739274f12 in __GI___assert_fail (assertion=0x55a2928756d8 "btr_validate_index(index, 0, false)", file=0x55a292875080 "/data/src/10.3/storage/innobase/row/row0upd.cc", line=2442, function=0x55a292877f40 <row_upd_sec_index_entry(upd_node_t*, que_thr_t*)::__PRETTY_FUNCTION__> "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
|
#8 0x000055a2920f9273 in row_upd_sec_index_entry (node=0x7f36e00a4bd0, thr=0x7f36e00a4f38) at /data/src/10.3/storage/innobase/row/row0upd.cc:2442
|
#9 0x000055a2920f9c30 in row_upd_sec_step (node=0x7f36e00a4bd0, thr=0x7f36e00a4f38) at /data/src/10.3/storage/innobase/row/row0upd.cc:2566
|
#10 0x000055a2920fc9f2 in row_upd (node=0x7f36e00a4bd0, thr=0x7f36e00a4f38) at /data/src/10.3/storage/innobase/row/row0upd.cc:3336
|
#11 0x000055a2920fce3f in row_upd_step (thr=0x7f36e00a4f38) at /data/src/10.3/storage/innobase/row/row0upd.cc:3451
|
#12 0x000055a29208e158 in row_update_for_mysql (prebuilt=0x7f36e00a4030) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1888
|
#13 0x000055a291ef7945 in ha_innobase::update_row (this=0x7f36e000a608, old_row=0x7f36e00a5d20 "\241\003", new_row=0x7f36e00a5d00 "\371\003") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:8838
|
#14 0x000055a291cd5660 in handler::ha_update_row (this=0x7f36e000a608, old_data=0x7f36e00a5d20 "\241\003", new_data=0x7f36e00a5d00 "\371\003") at /data/src/10.3/sql/handler.cc:6479
|
#15 0x000055a29196c5b6 in write_record (thd=0x7f36e0000af0, table=0x7f36e00a33f0, info=0x7f372e5fbbb0) at /data/src/10.3/sql/sql_insert.cc:1953
|
#16 0x000055a291969ade in mysql_insert (thd=0x7f36e0000af0, table_list=0x7f36e0012918, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_REPLACE, ignore=false) at /data/src/10.3/sql/sql_insert.cc:1072
|
#17 0x000055a2919ad79f in mysql_execute_command (thd=0x7f36e0000af0) at /data/src/10.3/sql/sql_parse.cc:4454
|
#18 0x000055a2919b907b in mysql_parse (thd=0x7f36e0000af0, rawbuf=0x7f36e0012818 "REPLACE INTO t1 (a,b) VALUES (3,2),(3,2)", length=40, parser_state=0x7f372e5fc5e0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7817
|
#19 0x000055a2919a5c07 in dispatch_command (command=COM_QUERY, thd=0x7f36e0000af0, packet=0x7f36e0165511 "REPLACE INTO t1 (a,b) VALUES (3,2),(3,2)", packet_length=40, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1856
|
#20 0x000055a2919a454f in do_command (thd=0x7f36e0000af0) at /data/src/10.3/sql/sql_parse.cc:1401
|
#21 0x000055a291b1c0c8 in do_handle_one_connection (connect=0x55a29417adc0) at /data/src/10.3/sql/sql_connect.cc:1403
|
#22 0x000055a291b1be2a in handle_one_connection (arg=0x55a29417adc0) at /data/src/10.3/sql/sql_connect.cc:1308
|
#23 0x000055a2924cc36a in pfs_spawn_thread (arg=0x55a294195e70) at /data/src/10.3/storage/perfschema/pfs.cc:1869
|
#24 0x00007f373b1fd4a4 in start_thread (arg=0x7f372e5fd700) at pthread_create.c:456
|
#25 0x00007f3739331d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
The debug version is slightly different on 10.4+:
|
10.4 debug ba679ae5 |
2 fields): {[8] '(0x0000000000000027),[6] (0x000000000200)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8] $(0x0000000000000024),[6] (0x000000000202)}
|
mysqld: /data/src/10.4/storage/innobase/row/row0upd.cc:2422: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `btr_validate_index(index, 0)' failed.
|
200327 15:20:17 [ERROR] mysqld got signal 6 ;
|
|
|
#6 0x00007fcac1999e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55d8078e3a0d "btr_validate_index(index, 0)", file=file@entry=0x55d8078e3270 "/data/src/10.4/storage/innobase/row/row0upd.cc", line=line@entry=2422, function=function@entry=0x55d8078e60e0 <row_upd_sec_index_entry(upd_node_t*, que_thr_t*)::__PRETTY_FUNCTION__> "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:92
|
#7 0x00007fcac1999f12 in __GI___assert_fail (assertion=0x55d8078e3a0d "btr_validate_index(index, 0)", file=0x55d8078e3270 "/data/src/10.4/storage/innobase/row/row0upd.cc", line=2422, function=0x55d8078e60e0 <row_upd_sec_index_entry(upd_node_t*, que_thr_t*)::__PRETTY_FUNCTION__> "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
|
#8 0x000055d8070e9719 in row_upd_sec_index_entry (node=0x7fca6818a648, thr=0x7fca6818a9b0) at /data/src/10.4/storage/innobase/row/row0upd.cc:2422
|
#9 0x000055d8070ea0c1 in row_upd_sec_step (node=0x7fca6818a648, thr=0x7fca6818a9b0) at /data/src/10.4/storage/innobase/row/row0upd.cc:2546
|
#10 0x000055d8070ed0e2 in row_upd (node=0x7fca6818a648, thr=0x7fca6818a9b0) at /data/src/10.4/storage/innobase/row/row0upd.cc:3327
|
#11 0x000055d8070ed528 in row_upd_step (thr=0x7fca6818a9b0) at /data/src/10.4/storage/innobase/row/row0upd.cc:3442
|
#12 0x000055d807088e63 in row_update_for_mysql (prebuilt=0x7fca68189aa0) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1889
|
#13 0x000055d806ee4464 in ha_innobase::update_row (this=0x7fca681892a8, old_row=0x7fca6800b430 "\241\003", new_row=0x7fca6800b410 "\371\003") at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:8830
|
#14 0x000055d806ca461a in handler::ha_update_row (this=0x7fca681892a8, old_data=0x7fca6800b430 "\241\003", new_data=0x7fca6800b410 "\371\003") at /data/src/10.4/sql/handler.cc:6722
|
#15 0x000055d8068e8b83 in write_record (thd=0x7fca68000af0, table=0x7fca6800a5a0, info=0x7fcabc143490) at /data/src/10.4/sql/sql_insert.cc:1976
|
#16 0x000055d8068e5f01 in mysql_insert (thd=0x7fca68000af0, table_list=0x7fca68013298, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_REPLACE, ignore=false) at /data/src/10.4/sql/sql_insert.cc:1078
|
#17 0x000055d806934467 in mysql_execute_command (thd=0x7fca68000af0) at /data/src/10.4/sql/sql_parse.cc:4528
|
#18 0x000055d806940bf1 in mysql_parse (thd=0x7fca68000af0, rawbuf=0x7fca68013198 "REPLACE INTO t1 (a,b) VALUES (3,2),(3,2)", length=40, parser_state=0x7fcabc144160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
|
#19 0x000055d80692bdc0 in dispatch_command (command=COM_QUERY, thd=0x7fca68000af0, packet=0x7fca68137141 "REPLACE INTO t1 (a,b) VALUES (3,2),(3,2)", packet_length=40, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
|
#20 0x000055d80692a44d in do_command (thd=0x7fca68000af0) at /data/src/10.4/sql/sql_parse.cc:1360
|
#21 0x000055d806ab39b3 in do_handle_one_connection (connect=0x55d80a24f170) at /data/src/10.4/sql/sql_connect.cc:1412
|
#22 0x000055d806ab3702 in handle_one_connection (arg=0x55d80a24f170) at /data/src/10.4/sql/sql_connect.cc:1316
|
#23 0x000055d8074bc0a1 in pfs_spawn_thread (arg=0x55d80a5ab770) at /data/src/10.4/storage/perfschema/pfs.cc:1869
|
#24 0x00007fcac39224a4 in start_thread (arg=0x7fcabc145700) at pthread_create.c:456
|
#25 0x00007fcac1a56d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Reproducible on 10.3-10.5.
The test case is not applicable to previous versions.
Attachments
Issue Links
- is duplicated by
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Stalled
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Open
-
-
-
- Closed
-
(5 relates to)
Activity
I can repeat this with a single transaction. The problem seems to be in the REPLACE implementation.
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 ( |
a int, |
b int, |
row_start bigint(20) unsigned GENERATED ALWAYS AS ROW START, |
row_end bigint(20) unsigned GENERATED ALWAYS AS ROW END, |
UNIQUE KEY (b,row_end), |
KEY (row_start), |
PERIOD FOR SYSTEM_TIME (row_start,row_end) |
) ENGINE=InnoDB WITH SYSTEM VERSIONING; |
|
|
BEGIN; |
INSERT INTO t1 (a,b) VALUES (1,2); |
REPLACE t1 (a,b) VALUES(3,2); |
REPLACE t1 (a,b) VALUES(3,2); |
COMMIT; |
|
|
# Cleanup
|
DROP TABLE t1; |
The INSERT part of each REPLACE will be rolled back, which you can observe by setting a breakpoint to row_undo_step. As far as I can tell, they looked OK to me: the savepoint would be only 1 less than the trx_t::undo_no.
I tried splitting up either REPLACE operation into INSERT IGNORE and UPDATE, but the problem did not reproduce. This strongly suggests a flaw in the system versioning logic.
Note: the column b only exists so that the unique index on it can cause a rollback of the INSERT part of REPLACE. If you change the values b=2 to b=NULL, no rollback will be initiated because no duplicates occur, and the test will not fail.
Here are a couple variations of the test that do not fail. First, splitting one of the REPLACE:
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 ( |
a int, |
b int, |
row_start bigint(20) unsigned GENERATED ALWAYS AS ROW START, |
row_end bigint(20) unsigned GENERATED ALWAYS AS ROW END, |
UNIQUE KEY (b,row_end), |
KEY (row_start), |
PERIOD FOR SYSTEM_TIME (row_start,row_end) |
) ENGINE=InnoDB WITH SYSTEM VERSIONING; |
|
|
BEGIN; |
INSERT INTO t1 (a,b) VALUES (1,2); |
INSERT IGNORE INTO t1 (a,b) VALUES(3,2); |
UPDATE t1 SET a=3; |
REPLACE t1 (a,b) VALUES(3,2); |
COMMIT; |
|
|
# Cleanup
|
DROP TABLE t1; |
Second, removing the unique index and instead triggering partial rollbacks explicitly:
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 ( |
a int, |
row_start bigint(20) unsigned GENERATED ALWAYS AS ROW START, |
row_end bigint(20) unsigned GENERATED ALWAYS AS ROW END, |
KEY (row_start), |
PERIOD FOR SYSTEM_TIME (row_start,row_end) |
) ENGINE=InnoDB WITH SYSTEM VERSIONING; |
|
|
BEGIN; |
INSERT INTO t1 SET a=1; |
SAVEPOINT a;
|
UPDATE t1 SET a=2; |
ROLLBACK TO SAVEPOINT a; |
INSERT INTO t1 SET a=3; |
SAVEPOINT b;
|
UPDATE t1 SET a=4; |
ROLLBACK TO SAVEPOINT b; |
INSERT INTO t1 SET a=5; |
COMMIT; |
|
|
# Cleanup
|
DROP TABLE t1; |
At the time of the crash, the clustered index GEN_CLUST_INDEX contains the following records in page 5:3:
(DB_ROW_ID,DB_TRX_ID,DB_ROLL_PTR,a,b,row_start,row_end)=(0x200,33,(update),3,2,0,~0),(0x202,33,(insert),1,2,30,33).
The index row_start contains the following records in page 5:5:
(row_start,DB_ROW_ID)=(0,0x200),delete-marked(30,0x200),(30,0x202).
At the start of ha_innobase::update_row(), the secondary index first only contains the record (30,0x200). It is delete-marked here:
10.5 d3bdc30c005b0307987b33b3a7356368e811686f
#0 mtr_t::write<1u, (mtr_t::write_type)0, unsigned char> (this=0x7ffff03d6f98, block=..., ptr=0x7ffff0b94078, val=32 ' ')at /mariadb/10.5m/storage/innobase/include/mtr0log.h:211#1 0x00005555564f9761 in btr_rec_set_deleted<true> (block=<optimized out>,rec=<optimized out>, mtr=<optimized out>)at /mariadb/10.5m/storage/innobase/btr/btr0cur.cc:5301#2 0x0000555556429740 in row_upd_sec_index_entry (node=0x7fffc00314a8,thr=0x7fffc0031810) at /mariadb/10.5m/storage/innobase/row/row0upd.cc:2140#3 row_upd_sec_step (node=0x7fffc00314a8, thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:2250#4 row_upd (node=0x7fffc00314a8, thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:3029#5 0x0000555556427961 in row_upd_step (thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:3144#6 0x00005555563cbe60 in row_update_for_mysql (prebuilt=<optimized out>)at /mariadb/10.5m/storage/innobase/row/row0mysql.cc:1889#7 0x000055555624a31d in ha_innobase::update_row (this=<optimized out>,old_row=0x7fffc001d568 "\241\001", new_row=0x7fffc001d548 "\371\003")at /mariadb/10.5m/storage/innobase/handler/ha_innodb.cc:8550The PAGE_HEAP_TOP is incremented to allocate space for another record:
10.5 d3bdc30c005b0307987b33b3a7356368e811686f
#0 page_mem_alloc_heap<false> (block=0x7ffff069b208, need=<optimized out>,heap_no=<optimized out>)at /mariadb/10.5m/storage/innobase/page/page0cur.cc:1061#1 page_cur_insert_rec_low (cur=<optimized out>, index=<optimized out>,rec=0x7fffc095629d "", offsets=<optimized out>, mtr=<optimized out>)at /mariadb/10.5m/storage/innobase/page/page0cur.cc:1376#2 0x00005555564dd72a in page_cur_tuple_insert (cursor=0x7ffff03d55c8,tuple=0x7fffc0955df8, index=<optimized out>, offsets=0x7ffff03d5588,heap=<optimized out>, n_ext=<optimized out>, mtr=<optimized out>)at /mariadb/10.5m/storage/innobase/include/page0cur.ic:284#3 0x00005555564dad9c in btr_cur_optimistic_insert (flags=0,cursor=0x7ffff03d55c0, offsets=0x7ffff03d5588, heap=0x7ffff03d55a0,entry=0x7fffc0955df8, rec=0x7ffff03d6660, big_rec=0x7ffff03d5660,n_ext=2, thr=0x7fffc0031810, mtr=0x7ffff03d61b8)at /mariadb/10.5m/storage/innobase/btr/btr0cur.cc:3537#4 0x00005555563a79a2 in row_ins_sec_index_entry_low (flags=<optimized out>,mode=<optimized out>, index=<optimized out>,offsets_heap=<optimized out>, heap=<optimized out>,entry=<optimized out>, trx_id=0, thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3113#5 0x00005555563aa726 in row_ins_sec_index_entry (index=<optimized out>,entry=0x2, thr=0x7fffc0031810, check_foreign=<optimized out>)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3315#6 0x0000555556429b24 in row_upd_sec_index_entry (node=0x7fffc00314a8,thr=0x7fffc0031810) at /mariadb/10.5m/storage/innobase/row/row0upd.cc:2223The record that is being inserted is (0,0x200). So far, so good. Next, another record is inserted:
10.5 d3bdc30c005b0307987b33b3a7356368e811686f
#0 page_mem_alloc_heap<false> (block=0x7ffff069b208, need=<optimized out>,heap_no=<optimized out>)at /mariadb/10.5m/storage/innobase/page/page0cur.cc:1061#1 page_cur_insert_rec_low (cur=<optimized out>, index=<optimized out>,rec=0x7fffc09556bd "", offsets=<optimized out>, mtr=<optimized out>)at /mariadb/10.5m/storage/innobase/page/page0cur.cc:1376#2 0x00005555564dd72a in page_cur_tuple_insert (cursor=0x7ffff03d60e8,tuple=0x7fffc001efd8, index=<optimized out>, offsets=0x7ffff03d60a8,heap=<optimized out>, n_ext=<optimized out>, mtr=<optimized out>)at /mariadb/10.5m/storage/innobase/include/page0cur.ic:284#3 0x00005555564dad9c in btr_cur_optimistic_insert (flags=0,cursor=0x7ffff03d60e0, offsets=0x7ffff03d60a8, heap=0x7ffff03d60c0,entry=0x7fffc001efd8, rec=0x7ffff03d7180, big_rec=0x7ffff03d6180,n_ext=2, thr=0x7fffc0031188, mtr=0x7ffff03d6cd8)at /mariadb/10.5m/storage/innobase/btr/btr0cur.cc:3537#4 0x00005555563a79a2 in row_ins_sec_index_entry_low (flags=<optimized out>,mode=<optimized out>, index=<optimized out>,offsets_heap=<optimized out>, heap=<optimized out>,entry=<optimized out>, trx_id=0, thr=0x7fffc0031188)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3113#5 0x00005555563aa726 in row_ins_sec_index_entry (index=<optimized out>,entry=0x2, thr=0x7fffc0031188, check_foreign=<optimized out>)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3315#6 0x00005555563abdb7 in row_ins_index_entry (index=0x7fffc0021bb8,entry=0x7fffc001efd8, thr=0x7fffc0031188)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3362#7 row_ins_index_entry_step (node=0x7fffc0030ed8, thr=0x7fffc0031188)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3529#8 row_ins (node=0x7fffc0030ed8, thr=<optimized out>)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3665#9 row_ins_step (thr=<optimized out>)at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3808#10 0x00005555563ca9b0 in row_insert_for_mysql (mysql_rec=<optimized out>,prebuilt=<optimized out>, ins_mode=ROW_INS_HISTORICAL) at /mariadb/10.5m/storage/innobase/row/row0mysql.cc:1463#11 0x000055555624a36d in ha_innobase::update_row (this=<optimized out>, old_row=0x7fffc001d568 "\241\001", new_row=0x7fffc001d548 "\371\003") at /mariadb/10.5m/storage/innobase/handler/ha_innodb.cc:8556This is an extra call related to system-versioned tables. After this, the index contains (0,0x200),delete-marked(30,0x200), and the inserted value (0x30,0x202).
On the second call to ha_innobase::update_row(), nothing will be changed in the indexes, and we will hit the error:
10.5 d3bdc30c005b0307987b33b3a7356368e811686f
#0 row_upd_sec_index_entry (node=0x7fffc00314a8, thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:2118#1 row_upd_sec_step (node=0x7fffc00314a8, thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:2250#2 row_upd (node=0x7fffc00314a8, thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:3029#3 0x0000555556427961 in row_upd_step (thr=0x7fffc0031810)at /mariadb/10.5m/storage/innobase/row/row0upd.cc:3144#4 0x00005555563cbe60 in row_update_for_mysql (prebuilt=<optimized out>)at /mariadb/10.5m/storage/innobase/row/row0mysql.cc:1889#5 0x000055555624a31d in ha_innobase::update_row (this=<optimized out>,old_row=0x7fffc001d568 "\241\003", new_row=0x7fffc001d548 "\371\003")at /mariadb/10.5m/storage/innobase/handler/ha_innodb.cc:8550We expect to find a record (33,0x200), but the secondary index contains (0,0x200),delete-marked(30,0x200),(30,0x202).
Yes, the current transaction ID is 33, and I think that the start ID of the INSERT transaction must have been 30. The ID was incremented twice at the autocommit, to assign the versioning end ID, and to assign the transaction commit number.
Note: there is no record with row_start_id=30 in the clustered index. It seems that the update is wrong. The update vector consists of one element, which is referring to row_start by the clustered index field number:
$30 = {field_no = 5, orig_len = 0, exp = 0x0, new_val = {data = 0x7fffc095a6d8, ext = 0, spatial_status = 0, len = 8, type = {prtype = 18184, mtype = 6, len = 8, mbminlen = 0, mbmaxlen = 0}},old_v_val = 0x0}The node->row is dumped by dtuple_print() as follows:
DATA TUPLE: 7 fields;0: len 4; hex 80000003; asc ;;1: len 4; hex 80000002; asc ;;2: len 8; hex 0000000000000021; asc !;;3: len 8; hex ffffffffffffffff; asc ;;4: len 6; hex 000000000200; asc ;;5: len 6; hex 000000000021; asc !;;6: len 7; hex 04000001380317; asc 8 ;;It is a table row, that is, (a=3,b=2,row_start=33,row_end=~0,DB_ROW_ID=0x200,DB_TRX_ID=33,DB_ROLL_PTR=(update)). It should correspond to the value (0x200,33,(update),3,2,33,~0) in the clustered index. (At the time of the crash, the second-but-last field had been updated to 0).
We appear to be attempting to update row_start from 33 to node->update->fields.new_val.data which is pointing to the value 0 (8 bytes). It seems that the logic in ha_innobase::update_row() could be flawed. The failing call is the first one of these:
error = row_update_for_mysql(m_prebuilt);historical rows only once. */&& trx->id != table->vers_start_id()) {error = row_insert_for_mysql((byte*) old_row,m_prebuilt,ROW_INS_HISTORICAL);}I ran the test once more, setting a breakpoint to ha_innobase::update_row() only. At the start of the first call, the clustered index contains the following in page 5:3:
(DB_ROW_ID,DB_TRX_ID,DB_ROLL_PTR,a,b,row_start,row_end)=(0x200,0,1<<55,1,2,30,~0). Note that the DB_TRX_ID has been reset by
MDEV-12288. It probably was 30 originally.At the start of the second invocation of ha_innobase::update_row(), we have the following values in the clustered index:
(DB_ROW_ID,DB_TRX_ID,DB_ROLL_PTR,a,b,row_start,row_end)=(0x200,33,(update),3,2,31,~0),(0x202,33,(insert),1,2,30,33).
To exclude the impact of
MDEV-12288and disable the purge of history, I tried setting innodb_force_recovery=2, but the test still crashed.I think that this should be analyzed further by someone who knows how system versioning is supposed to work.
Side note: we are wasting 2+2 bytes in each row, because DB_TRX_ID is only 48 bits while the row_start and row_end are 64 bits.