[MDEV-17899] Instant ADD/DROP multiple failure assertions Created: 2018-12-04  Updated: 2018-12-11  Resolved: 2018-12-11

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

Type: Bug Priority: Major
Reporter: Aleksey Midenkov Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Blocks
blocks MDEV-17697 Broken versioning info after instant ... Closed
Problem/Incident
is caused by MDEV-15562 Instant DROP COLUMN or changing the o... Closed
is caused by MDEV-17793 Crash in purge after instant DROP and... Closed

 Description   

Reproduce 1

--source include/have_innodb.inc
--source include/have_debug.inc
 
set debug_dbug='+d,ib_commit_inplace_fail_1';
create or replace table t1 (a int, b int) engine=innodb;
--error ER_INTERNAL_ERROR
alter table t1 drop column b, algorithm=instant;
--error ER_INTERNAL_ERROR
alter table t1 drop column b, algorithm=instant;
 
drop table t1;

Result 1

#3  0x00007ffff6f32142 in __GI___assert_fail (assertion=0x16cca27 "index->id == btr_page_get_index_id(page)", file=0x16cc060 "/home/midenok/src/mariadb/10.4/src/storage/innobase/btr/btr0cur.cc", line=2608, function=0x16ccdd5 "dberr_t btr_cur_open_at_index_side_func(bool, dict_index_t *, ulint, btr_cur_t *, ulint, const char *, unsigned int, mtr_t *)") at assert.c:101
#4  0x00000000010735b2 in btr_cur_open_at_index_side_func (from_left=true, index=0x7fff88020a88, latch_mode=1, cursor=0x7ffff4033a68, level=0, file=0x166b2a0 "/home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc", line=156, mtr=0x7ffff4033c88) at /home/midenok/src/mariadb/10.4/src/storage/innobase/btr/btr0cur.cc:2608
#5  0x0000000000df29e7 in instant_metadata_lock (index=..., mtr=...) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:155
#6  0x0000000000e05602 in dict_table_t::prepare_instant (this=0x7fff880498c8, old=..., col_map=0x7fff88026978, first_alter_pos=@0x7fff88016260: 0) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:190
#7  0x0000000000e04fbc in ha_innobase_inplace_ctx::prepare_instant (this=0x7fff880160f0) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:971
#8  0x0000000000de1630 in prepare_inplace_alter_table_dict (ha_alter_info=0x7ffff4036848, altered_table=0x7fff880253c8, old_table=0x7fff8801d7c8, table_name=0x7fff8804b2d5 "t1", flags=33, flags2=80, fts_doc_id_col=18446744073709551615, add_fts_doc_id=false, add_fts_doc_id_idx=false) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:6388
#9  0x0000000000ddb20f in ha_innobase::prepare_inplace_alter_table (this=0x7fff880411b0, altered_table=0x7fff880253c8, ha_alter_info=0x7ffff4036848) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:7935
#10 0x0000000000b2d41e in handler::ha_prepare_inplace_alter_table (this=0x7fff880411b0, altered_table=0x7fff880253c8, ha_alter_info=0x7ffff4036848) at /home/midenok/src/mariadb/10.4/src/sql/handler.cc:4437
#11 0x00000000008c9945 in mysql_inplace_alter_table (thd=0x7fff88000cf8, table_list=0x7fff88014ef8, table=0x7fff8801d7c8, altered_table=0x7fff880253c8, ha_alter_info=0x7ffff4036848, inplace_supported=HA_ALTER_INPLACE_INSTANT, target_mdl_request=0x7ffff4036ee8, alter_ctx=0x7ffff4037098) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:7515
#12 0x00000000008c2ef7 in mysql_alter_table (thd=0x7fff88000cf8, new_db=0x7fff880053b0, new_name=0x7fff88005780, create_info=0x7ffff4038370, table_list=0x7fff88014ef8, alter_info=0x7ffff40382b8, order_num=0, order=0x0, ignore=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:9689
#13 0x000000000096a00f in Sql_cmd_alter_table::execute (this=0x7fff88015568, thd=0x7fff88000cf8) at /home/midenok/src/mariadb/10.4/src/sql/sql_alter.cc:491
#14 0x00000000007cd824 in mysql_execute_command (thd=0x7fff88000cf8) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:6290
#15 0x00000000007bf3e0 in mysql_parse (thd=0x7fff88000cf8, rawbuf=0x7fff88014df0 "alter table t1 drop column b, algorithm=instant", length=47, parser_state=0x7ffff403b640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:8092

(gdb) p index->id
$1 = 25
(gdb) p btr_page_get_index_id(page)
$2 = 0
(gdb) p index->name
$3 = {
  m_name = 0x7fff88022a88 "GEN_CLUST_INDEX"
}
(gdb) x/32bx page
0x7fffdc4d8000: 0xed    0xb8    0x06    0x58    0x00    0x00    0x00    0x03
0x7fffdc4d8008: 0xff    0xff    0xff    0xff    0xff    0xff    0xff    0xff
0x7fffdc4d8010: 0x00    0x00    0x00    0x00    0x00    0x02    0x31    0xe1
0x7fffdc4d8018: 0x45    0xbf    0x00    0x00    0x00    0x00    0x00    0x00

Reproduce 2

set debug_dbug='+d,ib_commit_inplace_fail_1';
create or replace table t1 (a int, b int);
alter table t1 add column c int, algorithm=instant;

Result 2

#3  0x00007ffff6f32142 in __GI___assert_fail (assertion=0x1672be8 "index->n_core_fields <= old_n_fields", file=0x166b2a0 "/home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc", line=683, function=0x1672b0f "void dict_table_t::rollback_instant(unsigned int, dict_col_t *, const char *, dict_instant_t *, dict_field_t *, unsigned int, unsigned int, dict_v_col_t *, const char *, const ulint *)") at assert.c:101
#4  0x0000000000e10123 in dict_table_t::rollback_instant (this=0x7fff8001e6c8, old_n_cols=5, old_cols=0x7fff8001fe48, old_col_names=0x7fff8001ff40 "a", old_instant=0x0, old_fields=0x7fff80022a98, old_n_fields=5, old_n_v_cols=0, old_v_cols=0x7fff8001fee8, old_v_col_names=0x0, col_map=0x7fff80032c28) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:683
#5  0x0000000000e006b8 in ha_innobase_inplace_ctx::rollback_instant (this=0x7fff80016590) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:988
#6  0x0000000000de7691 in ha_innobase::commit_inplace_alter_table (this=0x7fff80025850, altered_table=0x7fff80029f88, ha_alter_info=0x7ffff4036848, commit=true) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/handler0alter.cc:10676
#7  0x0000000000b2d56a in handler::ha_commit_inplace_alter_table (this=0x7fff80025850, altered_table=0x7fff80029f88, ha_alter_info=0x7ffff4036848, commit=true) at /home/midenok/src/mariadb/10.4/src/sql/handler.cc:4457
#8  0x00000000008c9e5b in mysql_inplace_alter_table (thd=0x7fff80000cf8, table_list=0x7fff80014f08, table=0x7fff80024c88, altered_table=0x7fff80029f88, ha_alter_info=0x7ffff4036848, inplace_supported=HA_ALTER_INPLACE_INSTANT, target_mdl_request=0x7ffff4036ee8, alter_ctx=0x7ffff4037098) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:7598
#9  0x00000000008c2ef7 in mysql_alter_table (thd=0x7fff80000cf8, new_db=0x7fff800053b0, new_name=0x7fff80005780, create_info=0x7ffff4038370, table_list=0x7fff80014f08, alter_info=0x7ffff40382b8, order_num=0, order=0x0, ignore=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:9689
#10 0x000000000096a00f in Sql_cmd_alter_table::execute (this=0x7fff80015668, thd=0x7fff80000cf8) at /home/midenok/src/mariadb/10.4/src/sql/sql_alter.cc:491
#11 0x00000000007cd824 in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:6290
#12 0x00000000007bf3e0 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80014df0 "alter table t1 add column c int, algorithm=instant", length=50, parser_state=0x7ffff403b640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:8092



 Comments   
Comment by Aleksey Midenkov [ 2018-12-11 ]

`Reproduce 1` is still affected.

Comment by Marko Mäkelä [ 2018-12-11 ]

Yes, there is something strange about the Reproduce 1. I did add the test to innodb.innodb_instant_debug, but it does not fail. It does fail when it is at the very start of a test file:

--source include/have_innodb.inc
--source include/have_debug.inc
 
set debug_dbug='+d,ib_commit_inplace_fail_1';
create table t1 (a int, b int) engine=innodb;
--error ER_INTERNAL_ERROR
alter table t1 drop column b;
--error ER_INTERNAL_ERROR
alter table t1 drop column b;
 
drop table t1;

The issue is that the index tree is being freed on rollback, triggering an assertion failure on subsequent access:

10.4 1c53aeff58e1b00348687bd3e73db53b3c90386f

mysqld: /mariadb/10.4/storage/innobase/btr/btr0cur.cc:2608: dberr_t btr_cur_open_at_index_side_func(bool, dict_index_t*, ulint, btr_cur_t*, ulint, const char*, unsigned int, mtr_t*): Assertion `index->id == btr_page_get_index_id(page)' failed.

The stack trace for the freeing is as follows:

#3  0x000055555637fed0 in btr_page_set_index_id (page=0x7ffff49dc000 "", 
    page_zip=0x0, id=0, mtr=0x7ffff41fd990)
    at /mariadb/10.4/storage/innobase/include/btr0btr.ic:94
#4  0x000055555638313e in btr_free_root_invalidate (block=0x7ffff44d23e0, 
    mtr=0x7ffff41fd990) at /mariadb/10.4/storage/innobase/btr/btr0btr.cc:1133
#5  0x0000555556383bc9 in btr_free_if_exists (page_id=..., page_size=..., 
    index_id=25, mtr=0x7ffff41fd990)
    at /mariadb/10.4/storage/innobase/btr/btr0btr.cc:1393
#6  0x000055555641d9b7 in dict_drop_index_tree (rec=0x7ffff450c4f9 "", 
    pcur=0x7fffa004c038, mtr=0x7ffff41fd990)
    at /mariadb/10.4/storage/innobase/dict/dict0crea.cc:974
#7  0x00005555564e881b in row_undo_ins_remove_clust_rec (node=0x7fffa004bfc8)
    at /mariadb/10.4/storage/innobase/row/row0uins.cc:133
#8  0x00005555564e9e4a in row_undo_ins (node=0x7fffa004bfc8, 
    thr=0x7fffa00210e8) at /mariadb/10.4/storage/innobase/row/row0uins.cc:588
#9  0x0000555556301ecc in row_undo (node=0x7fffa004bfc8, thr=0x7fffa00210e8)
    at /mariadb/10.4/storage/innobase/row/row0undo.cc:437
#10 0x0000555556302114 in row_undo_step (thr=0x7fffa00210e8)
    at /mariadb/10.4/storage/innobase/row/row0undo.cc:497
#11 0x00005555562671cc in que_thr_step (thr=0x7fffa00210e8)
    at /mariadb/10.4/storage/innobase/que/que0que.cc:1040
#12 0x000055555626741e in que_run_threads_low (thr=0x7fffa00210e8)
    at /mariadb/10.4/storage/innobase/que/que0que.cc:1104
#13 0x0000555556267610 in que_run_threads (thr=0x7fffa00210e8)
   /storage/innobase/que/que0que.cc:1144
#14 0x000055555635a364 in trx_rollback_to_savepoint_low (trx=0x7ffff4cf8208, 
    savept=0x0) at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:137
#15 0x000055555635a754 in trx_rollback_for_mysql_low (trx=0x7ffff4cf8208)
    at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:206
#16 0x000055555635aaa7 in trx_rollback_for_mysql (trx=0x7ffff4cf8208)
    at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:232
#17 0x00005555561a60d4 in ha_innobase::commit_inplace_alter_table (
    this=0x7fffa00261d0, altered_table=0x7fffa003fb78, 
    ha_alter_info=0x7ffff41ffb70, commit=true)
    at /mariadb/10.4/storage/innobase/handler/handler0alter.cc:10677

Why did this transaction insert anything into SYS_INDEXES in the first place? It is not creating any index or rebuilding the table.
The answer is that dict_table_t::reassign_id() (invoked by innobase_instant_try()) is updating the PRIMARY KEY of the existing record, which will be undo-logged as delete-marking and inserting. And the internal ‘trigger’ on rolling back the insert will wrongly drop the index tree.

Comment by Marko Mäkelä [ 2018-12-11 ]

The remaining problem is a regression caused by MDEV-17793. I may have to come up with an alternative fix that does not involve updating the table_id.

The other use of updating table_id was TRUNCATE TABLE until MDEV-13564 replaced that code.

Comment by Marko Mäkelä [ 2018-12-11 ]

I fixed the last failure by reimplementing the fix of MDEV-17793.

Generated at Thu Feb 08 08:39:59 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.