|
The memory was allocated by the same thread shortly before it was accessed:
|
mariadb-10.6.0
|
#1 0x00007f12fac73022 in __asan_poison_memory_region () from /lib/x86_64-linux-gnu/libasan.so.5
|
#2 0x000055c7e0ebcada in mem_heap_create_block_func (heap=0x0, n=160, file_name=0x55c7e22b7740 "/data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc", line=13592, type=0)
|
at /data/Server/10.6alpha/storage/innobase/mem/mem0mem.cc:333
|
#3 0x000055c7e0c95182 in mem_heap_create_func (size=160, file_name=0x55c7e22b7740 "/data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc", line=13592, type=0)
|
at /data/Server/10.6alpha/storage/innobase/include/mem0mem.ic:377
|
#4 0x000055c7e0cd4dc2 in ha_innobase::records_in_range (this=0x61d0003d18b8, keynr=0, min_key=0x690d1ba64580, max_key=0x0, pages=0x690d1ba64560)
|
at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13592
|
#5 0x000055c7e00adcf9 in handler::multi_range_read_info_const (this=0x61d0003d18b8, keyno=0, seq=0x690d1ba64850, seq_init_param=0x690d1ba648a0, n_ranges_arg=0, bufsz=0x690d1ba646e0, flags=0x690d1ba646d0,
|
cost=0x690d1ba65070) at /data/Server/10.6alpha/sql/multi_range_read.cc:177
|
#6 0x000055c7e00b8e12 in DsMrr_impl::dsmrr_info_const (this=0x61d0003d1d90, keyno=0, seq=0x690d1ba64850, seq_init_param=0x690d1ba648a0, n_ranges=0, bufsz=0x690d1ba64fa0, flags=0x690d1ba64f90,
|
cost=0x690d1ba65070) at /data/Server/10.6alpha/sql/multi_range_read.cc:1708
|
#7 0x000055c7e0cea3b4 in ha_innobase::multi_range_read_info_const (this=0x61d0003d18b8, keyno=0, seq=0x690d1ba64850, seq_init_param=0x690d1ba648a0, n_ranges=0, bufsz=0x690d1ba64fa0, flags=0x690d1ba64f90,
|
cost=0x690d1ba65070) at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:19522
|
The poisoned bytes are part of a safety margin inside mem_heap_t. The problematic access is being reported a little later:
|
mariadb-10.6.0
|
#0 0x00007f12fac78950 in __asan_report_load_n () from /lib/x86_64-linux-gnu/libasan.so.5
|
#1 0x000055c7e10a0e1c in row_sel_convert_mysql_key_to_innobase (tuple=0x612000099248, buf=0x62100003735c '\276' <repeats 20 times>, buf_len=8, index=0x6160012a8408, key_ptr=0x621000038594 "", key_len=5)
|
at /data/Server/10.6alpha/storage/innobase/row/row0sel.cc:2529
|
#2 0x000055c7e0cd509a in ha_innobase::records_in_range (this=0x61d0003d18b8, keynr=0, min_key=0x690d1ba64580, max_key=0x0, pages=0x690d1ba64560)
|
at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13601
|
Let us check the lines 13592 through 13601:
heap = mem_heap_create(2 * (key->ext_key_parts * sizeof(dfield_t)
|
+ sizeof(dtuple_t)));
|
|
range_start = dtuple_create(heap, key->ext_key_parts);
|
dict_index_copy_types(range_start, index, key->ext_key_parts);
|
|
range_end = dtuple_create(heap, key->ext_key_parts);
|
dict_index_copy_types(range_end, index, key->ext_key_parts);
|
|
row_sel_convert_mysql_key_to_innobase(
|
range_start,
|
m_prebuilt->srch_key_val1,
|
m_prebuilt->srch_key_val_len,
|
index,
|
(byte*) (min_key ? min_key->key : (const uchar*) 0),
|
(ulint) (min_key ? min_key->length : 0));
|
The invalid access is being reported for range_start->fields+1, which is garbage:
(rr) p *range_start
|
$11 = {info_bits = 0, n_fields = 18446744073709551614, n_fields_cmp = 18446744073709551614, fields = 0x612000099280, n_v_fields = 0, v_fields = 0x0, magic_n = 65478679}
|
(rr) p *range_start.fields
|
$12 = {data = 0x621000037358, ext = 0, spatial_status = 3, len = 4, type = {prtype = 1283, mtype = 6, len = 4, mbminlen = 0, mbmaxlen = 0}}
|
(rr) p range_start.fields[1]
|
$13 = {data = 0xbebebebebebebebe, ext = 0, spatial_status = 3, len = 3200171710, type = {prtype = 3200171710, mtype = 190, len = 48830, mbminlen = 6, mbmaxlen = 7}}
|
A little earlier, range_start was changed from 1 to ULINT_MAX or -2 fields. But this should not be the root cause of the failure. Maybe removing that assignment could have allowed us to catch the problem a little earlier.
#0 0x000055c7e12c6324 in dtuple_set_n_fields (tuple=0x612000099248, n_fields=18446744073709551614) at /data/Server/10.6alpha/storage/innobase/data/data0data.cc:125
|
#1 0x000055c7e10a0c55 in row_sel_convert_mysql_key_to_innobase (tuple=0x612000099248, buf=0x621000037358 '\276' <repeats 24 times>, buf_len=8, index=0x6160012a8408, key_ptr=0x621000038590 "\001", key_len=5)
|
at /data/Server/10.6alpha/storage/innobase/row/row0sel.cc:2506
|
#2 0x000055c7e0cd509a in ha_innobase::records_in_range (this=0x61d0003d18b8, keynr=0, min_key=0x690d1ba64580, max_key=0x0, pages=0x690d1ba64560)
|
at /data/Server/10.6alpha/storage/innobase/handler/ha_innodb.cc:13601
|
Let us check at what point the server was executing before it was killed by the test harness and before the failure of the subsequent server run that started with a recovery:
(rr) when
|
Current event: 567808
|
(rr) watch -l log_sys.flushed_to_disk_lsn
|
Hardware watchpoint 1: -location log_sys.flushed_to_disk_lsn
|
(rr) rc
|
Continuing.
|
…
|
Thread 4 hit Hardware watchpoint 1: -location log_sys.flushed_to_disk_lsn
|
|
Old value = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 8101754}, <No data fields>}
|
New value = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 8101711}, <No data fields>}
|
0x000055e53f5e63a1 in std::__atomic_base<unsigned long>::store (__m=std::memory_order_release, __i=8101754, this=0x55e5427e4408 <log_sys+8>) at /usr/include/c++/9/bits/atomic_base.h:397
|
397 __atomic_store_n(&_M_i, __i, int(__m));
|
(rr) bt
|
#0 0x000055e53f5e63a1 in std::__atomic_base<unsigned long>::store (__m=std::memory_order_release, __i=8101754, this=0x55e5427e4408 <log_sys+8>) at /usr/include/c++/9/bits/atomic_base.h:397
|
#1 log_t::set_flushed_lsn (this=0x55e5427e4400 <log_sys>, lsn=8101754) at /data/Server/10.6alpha/storage/innobase/include/log0log.h:656
|
#2 0x000055e53f5e026f in log_write_flush_to_disk_low (lsn=8101754) at /data/Server/10.6alpha/storage/innobase/log/log0log.cc:629
|
#3 0x000055e53f5e13a7 in log_write_up_to (lsn=8101754, flush_to_disk=true, rotate_key=false, callback=0x7f3ffb184dc0) at /data/Server/10.6alpha/storage/innobase/log/log0log.cc:830
|
#4 0x000055e53f8fe839 in trx_flush_log_if_needed_low (lsn=8101754, trx_state=TRX_STATE_COMMITTED_IN_MEMORY) at /data/Server/10.6alpha/storage/innobase/trx/trx0trx.cc:1205
|
#5 0x000055e53f8fe920 in trx_flush_log_if_needed (lsn=8101754, trx=0x51c22490bb80) at /data/Server/10.6alpha/storage/innobase/trx/trx0trx.cc:1226
|
#6 0x000055e53f908562 in trx_t::commit_in_memory (this=0x51c22490bb80, mtr=0x7f3ffb1853c0) at /data/Server/10.6alpha/storage/innobase/trx/trx0trx.cc:1414
|
#7 0x000055e53f8ffa5e in trx_t::commit_low (this=0x51c22490bb80, mtr=0x7f3ffb1853c0) at /data/Server/10.6alpha/storage/innobase/trx/trx0trx.cc:1505
|
#8 0x000055e53f8ffb93 in trx_t::commit (this=0x51c22490bb80) at /data/Server/10.6alpha/storage/innobase/trx/trx0trx.cc:1519
|
#9 0x000055e53f4ec26c in ha_innobase::commit_inplace_alter_table (this=0x61d0007116b8, altered_table=0x7f3ffb187840, ha_alter_info=0x7f3ffb187150, commit=true)
|
at /data/Server/10.6alpha/storage/innobase/handler/handler0alter.cc:11173
|
#10 0x000055e53eb302ca in handler::ha_commit_inplace_alter_table (this=0x61d0007116b8, altered_table=0x7f3ffb187840, ha_alter_info=0x7f3ffb187150, commit=true) at /data/Server/10.6alpha/sql/handler.cc:4863
|
#11 0x000055e53e601739 in mysql_inplace_alter_table (thd=0x62b0001f8218, table_list=0x62b0002303f0, table=0x619000a52898, altered_table=0x7f3ffb187840, ha_alter_info=0x7f3ffb187150,
|
target_mdl_request=0x7f3ffb187240, alter_ctx=0x7f3ffb1882b0) at /data/Server/10.6alpha/sql/sql_table.cc:8177
|
#12 0x000055e53e61376b in mysql_alter_table (thd=0x62b0001f8218, new_db=0x62b0001fcc38, new_name=0x62b0001fd060, create_info=0x7f3ffb189640, table_list=0x62b0002303f0, alter_info=0x7f3ffb189510, order_num=0,
|
order=0x0, ignore=false, if_exists=false) at /data/Server/10.6alpha/sql/sql_table.cc:10788
|
#13 0x000055e53e7871ef in Sql_cmd_alter_table::execute (this=0x62b000230c18, thd=0x62b0001f8218) at /data/Server/10.6alpha/sql/sql_alter.cc:540
|
#14 0x000055e53e3a82ad in mysql_execute_command (thd=0x62b0001f8218) at /data/Server/10.6alpha/sql/sql_parse.cc:5986
|
#15 0x000055e53e3b4738 in mysql_parse (thd=0x62b0001f8218, rawbuf=0x62b000230238 "ALTER TABLE t1 MODIFY COLUMN col_int INTEGER NOT NULL, ALGORITHM = INPLACE /* E_R Thread1 QNO 7321 CON_ID 54 */", length=112,
|
parser_state=0x7f3ffb18ab20) at /data/Server/10.6alpha/sql/sql_parse.cc:8018
|
#16 0x000055e53e38d022 in dispatch_command (command=COM_QUERY, thd=0x62b0001f8218,
|
packet=0x62900000f219 " ALTER TABLE t1 MODIFY COLUMN col_int INTEGER NOT NULL, ALGORITHM = INPLACE /* E_R Thread1 QNO 7321 CON_ID 54 */ ", packet_length=114, blocking=true)
|
at /data/Server/10.6alpha/sql/sql_parse.cc:1897
|
…
|
(rr) finish
|
Run till exit from #0 0x000055e53f5e63a1 in std::__atomic_base<unsigned long>::store (__m=std::memory_order_release, __i=8101754, this=0x55e5427e4408 <log_sys+8>) at /usr/include/c++/9/bits/atomic_base.h:397
|
…
|
(rr) finish
|
Run till exit from #0 trx_t::commit (this=0x51c22490bb80) at /data/Server/10.6alpha/storage/innobase/trx/trx0trx.cc:1512
|
ha_innobase::commit_inplace_alter_table (this=0x61d0007116b8, altered_table=0x7f3ffb187840, ha_alter_info=0x7f3ffb187150, commit=true) at /data/Server/10.6alpha/storage/innobase/handler/handler0alter.cc:11180
|
11180 DBUG_EXECUTE_IF("innodb_alter_commit_crash_after_commit",
|
(rr) when
|
Current event: 567694
|
(rr) finish
|
Run till exit from #0 ha_innobase::commit_inplace_alter_table (this=0x61d0007116b8, altered_table=0x7f3ffb187840, ha_alter_info=0x7f3ffb187150, commit=true)
|
at /data/Server/10.6alpha/storage/innobase/handler/handler0alter.cc:11180
|
|
Thread 3 received signal SIGKILL, Killed.
|
[Switching to Thread 3972606.3973052]
|
0x0000000070000002 in ?? ()
|
(rr) when
|
Current event: 567808
|
Based on this excerpt, it is obvious that the ALTER TABLE operation was committed inside InnoDB but the .frm file was not updated before the server was killed. Thus, we would have type mismatch for the column col_int.
This kind of crashes can occur until MDEV-25180 and MDEV-17567 have been fixed. It should not occur with those fixes. Unfortunately, Atomic DDL did not make it to the 10.6.0 release.
|