|
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:8550
|
The 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:2223
|
The 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:8556
|
This 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:8550
|
We 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);
|
|
if (error == DB_SUCCESS && vers_ins_row
|
/* Multiple UPDATE of same rows in single transaction create
|
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-12288 and 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.
|