Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-29144

ER_TABLE_SCHEMA_MISMATCH or InnoDB: Failing assertion: index != 0 upon IMPORT TABLESPACE

    XMLWordPrintable

    Details

      Description

      The test case is highly non-determinstic, run with a high value of repeat=N. It usually fails for me within several dozen attempts, but it can vary a lot on different machines and builds.

      The compound block in the test case is irrelevant to the problem, it is used to get better concurrency within MTR. Instead, the same results can be achieved by running ALTER concurrently with a single UPDATE (send ALTER => run UPDATE => reap ALTER), but then it takes longer to reproduce.

      The failure happens only when ALTER ends with ER_LOCK_WAIT_TIMEOUT. However, it doesn't always happen when ALTER ends with the timeout; apparently, a much thiner concurrency is involved, at least I couldn't serialize it neither on the SQL level nor via existing sync points in sql_table/sql_base.

      --source include/have_innodb.inc
      --source include/have_sequence.inc
       
      CREATE TABLE t (pk int, c varchar(1024), primary key (pk)) ENGINE=InnoDB CHARSET latin1;
      INSERT INTO t SELECT seq, 'x' FROM seq_1_to_100;
       
      --connect (con1,localhost,root,,test)
      --delimiter $
      --send
        BEGIN NOT ATOMIC
          DECLARE a INT DEFAULT 0;
          REPEAT
            SET a= a+1;
            UPDATE t SET c = 'xx' WHERE pk = a;
          UNTIL a = 100
          END REPEAT;
        END
      $
      --delimiter ;
       
      --connection default  
      --error 0,ER_LOCK_WAIT_TIMEOUT
      ALTER TABLE t NOWAIT ADD INDEX (c);
       
      --connection con1
      --reap
       
      --connection default
       
      --let $datadir= `select @@datadir`
       
      FLUSH TABLE t FOR EXPORT;
      --let $create= query_get_value(SHOW CREATE TABLE t, Create Table, 1)
      --echo $create
      --copy_file $datadir/test/t.cfg $MYSQL_TMP_DIR/t.cfg
      --copy_file $datadir/test/t.ibd $MYSQL_TMP_DIR/t.ibd
      UNLOCK TABLES;
       
      DROP TABLE t;
      eval $create;
       
      ALTER TABLE t DISCARD TABLESPACE;
      --move_file $MYSQL_TMP_DIR/t.cfg $datadir/test/t.cfg
      --move_file $MYSQL_TMP_DIR/t.ibd $datadir/test/t.ibd
      ALTER TABLE t IMPORT TABLESPACE;
       
      # Cleanup
      DROP TABLE t;
      

      So, the test creates/populates a table, then runs some DML on it and inplace ALTER .. ADD INDEX in parallel. ADD INDEX fails, the table seemingly doesn't get the index (neither show create nor I_S tables show it), but when the tablespace is imported in an identical table, it complains about an extra index in meta-data:

      10.4 8911823f, similar on 10.3-10.10

      mysqltest: At line 45: query 'ALTER TABLE t IMPORT TABLESPACE' failed: 1808: Schema mismatch (Number of indexes don't match, table has 1 indexes but the tablespace meta-data file has 2 indexes)
      

      If we modify the test case slightly, removing this two lines:

      DROP TABLE t;
      eval $create;
      

      – that is, instead of re-creating the table from scratch, we re-import the tablespace into the original one – it causes an assertion failure instead:

      10.4 8911823f, similar on 10.4-10.10

      2022-07-21 00:15:14 0x7f5ae5fdb700  InnoDB: Assertion failure in file /data/src/10.4/storage/innobase/row/row0import.cc line 1403
      InnoDB: Failing assertion: index != 0
       
      #6  0x000056260b659a5e in ut_dbg_assertion_failed (expr=0x56260bc7c087 "index != 0", file=0x56260bc7b768 "/data/src/10.4/storage/innobase/row/row0import.cc", line=1403) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
      No locals.
      #7  0x000056260b53d87c in row_import::set_root_by_name (this=0x7f5ae5fd8ec0) at /data/src/10.4/storage/innobase/row/row0import.cc:1403
              index = 0x0
              index_name = 0x7f5a940616d0 "c"
              i = 1
              cfg_index = 0x7f5a94061920
      #8  0x000056260b546713 in row_import_for_mysql (table=0x7f5a940d50e0, prebuilt=0x7f5a980326e0) at /data/src/10.4/storage/innobase/row/row0import.cc:4452
              err = DB_SUCCESS
              trx = 0x7f5ae6a74218
              autoinc = 0
              filepath = 0x0
              space_flags = 140028382393816
              __PRETTY_FUNCTION__ = "dberr_t row_import_for_mysql(dict_table_t*, row_prebuilt_t*)"
              cfg = {m_table = 0x7f5a940d50e0, m_version = 1, m_hostname = 0x7f5a941a2dc0 "tomahawk-d11", m_table_name = 0x7f5a940a1560 "test/t", m_autoinc = 0, m_zip_size = 0, m_flags = 33, m_n_cols = 5, m_cols = 0x7f5a94061600, m_col_names = 0x7f5a940d6040, m_n_indexes = 2, m_indexes = 0x7f5a940618a0, m_missing = false}
              converter = {<AbstractCallback> = {_vptr.AbstractCallback = 0x7f5ae5fd9090, m_zip_size = 140028567049672, m_file = {m_file = 0, m_psi = 0x7f5ae5fd8f58}, m_filepath = 0x0, m_trx = 0x56260c0e2638, m_space = 130843, m_size = 3858599840, m_xdes = 0x56260b9f1a2d "MDL_context::acquire_lock", m_xdes_page_no = 0, m_space_flags = 140028382384032}, m_cfg = 0x100000b8b93bc, m_index = 0x7f5ae5fd8fc0, m_current_lsn = 94721402604039, m_page_zip_ptr = 0x7f5ae5fd8fc0, m_rec_iter = {m_cur = {index = 0x7f5a94000cd0, rec = 0x7f5a94000cd0 "\353\255/\250\374\177", offsets = 0x194000cb0, block = 0x7f5ae5fd9200}}, m_offsets_ = {64633, 2957, 0, 0, 61930, 2969, 22054, 0, 0, 0, 0, 0, 36864, 58877, 32602, 0, 37820, 2955, 0, 1, 36896, 58877, 32602, 0, 2567, 2958, 22054, 0, 36896, 58877, 32602, 0, 3280, 37888, 32602, 0, 3280, 37888, 32602, 0, 3248, 37888, 1, 0, 37472, 58877, 32602, 0, 64633, 2957, 0, 0, 19880, 2971, 22054, 0, 0, 0, 0, 0, 36960, 58877, 32602, 0, 37820, 2955, 0, 1, 36992, 58877, 32602, 0, 2567, 2958, 22054, 0, 36992, 58877, 32602, 0, 3280, 37888, 32602, 0, 3280, 37888, 32602, 0, 3248, 37888, 1, 0, 37568, 58877, 32602, 0, 64633, 2957, 22054, 0, 37056, 58877, 32602, 0, 37600, 58877, 0, 0, 54505, 3008, 22054, 0, 0, 0, 0, 0, 37072, 58877, 32602, 0, 37820, 2955, 0, 0, 19880, 2971, 22054, 0, 0, 0, 0, 0, 37104, 58877, 32602, 0, 37820, 2955, 0, 1, 37136, 58877, 32602, 0, 2567, 2958, 22054, 0, 37136, 58877, 32602, 0, 3280, 37888, 32602, 0, 3280, 37888, 32602, 0, 3248, 37888, 1, 0, 37712, 58877, 32602, 0, 64633, 2957, 22054, 0, 37200, 58877, 32602, 0, 37744, 58877, 0, 0, 54505, 3008, 22054, 0, 0, 0, 0, 0, 37216, 58877, 32602, 0, 37820, 2955, 0, 1, 37248, 58877, 32602, 0...}, m_offsets = 0x7f5ae5fd9240, m_heap = 0x100000b8b93bc, m_cluster_index = 0x7f5ae5fd9260}
              fsp_flags = 0
              index = 0x13f008eec457be00
      #9  0x000056260b3ddfe5 in ha_innobase::discard_or_import_tablespace (this=0x7f5a98031638, discard=0 '\000') at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:13160
              _db_stack_frame_ = {func = 0x56260b9cfbb0 "mysql_discard_or_import_tablespace", file = 0x56260b9cdd38 "/data/src/10.4/sql/sql_table.cc", level = 2147483654, line = -1, prev = 0x7f5ae5fd9a60}
              err = DB_SUCCESS
      #10 0x000056260b0020bd in handler::ha_discard_or_import_tablespace (this=0x7f5a98031638, discard=0 '\000') at /data/src/10.4/sql/handler.cc:4626
              __PRETTY_FUNCTION__ = "int handler::ha_discard_or_import_tablespace(my_bool)"
      #11 0x000056260ada94f7 in mysql_discard_or_import_tablespace (thd=0x7f5a94000d90, table_list=0x7f5a94014888, discard=false) at /data/src/10.4/sql/sql_table.cc:6093
              alter_prelocking_strategy = {<Prelocking_strategy> = {_vptr.Prelocking_strategy = 0x56260c12c628 <vtable for Alter_table_prelocking_strategy+16>}, <No data fields>}
              error = 6740
              _db_stack_frame_ = {func = 0x56260b9b1930 "mysql_execute_command", file = 0x56260b9b0cc8 "/data/src/10.4/sql/sql_parse.cc", level = 2147483653, line = -1, prev = 0x7f5ae5fd9c80}
      #12 0x000056260ae4f77a in Sql_cmd_discard_import_tablespace::execute (this=0x7f5a94014f58, thd=0x7f5a94000d90) at /data/src/10.4/sql/sql_alter.cc:557
              select_lex = 0x7f5a940054c8
              table_list = 0x7f5a94014888
      #13 0x000056260acc6bfe in mysql_execute_command (thd=0x7f5a94000d90) at /data/src/10.4/sql/sql_parse.cc:6192
              res = 0
              up_result = 0
              lex = 0x7f5a94004c00
              select_lex = 0x7f5a940054c8
              first_table = 0x7f5a94014888
              all_tables = 0x7f5a94014888
              unit = 0x7f5a94004cc0
              have_table_map_for_update = false
              rpl_filter = 0x56260b11b07d <inline_mysql_mutex_unlock(mysql_mutex_t*, char const*, uint)+107>
              _db_stack_frame_ = {func = 0x56260b9b2bb8 "mysql_parse", file = 0x56260b9b0cc8 "/data/src/10.4/sql/sql_parse.cc", level = 2147483652, line = -1, prev = 0x7f5ae5fda250}
              __PRETTY_FUNCTION__ = "int mysql_execute_command(THD*)"
              ots = {ctx = 0x7f5a940048e0, traceable = false}
              trace_command = {<Json_writer_struct> = {_vptr.Json_writer_struct = 0x56260c12a510 <vtable for Json_writer_object+16>, my_writer = 0x0, context = {writer = 0x0}, closed = false}, <No data fields>}
              trace_command_steps = {<Json_writer_struct> = {_vptr.Json_writer_struct = 0x56260c12a4f0 <vtable for Json_writer_array+16>, my_writer = 0x0, context = {writer = 0x0}, closed = false}, <No data fields>}
              orig_binlog_format = BINLOG_FORMAT_MIXED
              orig_current_stmt_binlog_format = BINLOG_FORMAT_STMT
      #14 0x000056260accbefa in mysql_parse (thd=0x7f5a94000d90, rawbuf=0x7f5a940147a8 "ALTER TABLE t IMPORT TABLESPACE", length=31, parser_state=0x7f5ae5fda410, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7995
              found_semicolon = 0x0
              error = 32602
              lex = 0x7f5a94004c00
              err = false
              _db_stack_frame_ = {func = 0x56260b9b113a "dispatch_command", file = 0x56260b9b0cc8 "/data/src/10.4/sql/sql_parse.cc", level = 2147483651, line = -1, prev = 0x7f5ae5fda3f0}
              __PRETTY_FUNCTION__ = "void mysql_parse(THD*, char*, uint, Parser_state*, bool, bool)"
      #15 0x000056260acb839a in dispatch_command (command=COM_QUERY, thd=0x7f5a94000d90, packet=0x7f5a9400ac01 "ALTER TABLE t IMPORT TABLESPACE", packet_length=31, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1857
              packet_end = 0x7f5a940147c7 ""
              parser_state = {m_lip = {lookahead_token = -1, lookahead_yylval = 0x0, m_thd = 0x7f5a94000d90, m_ptr = 0x7f5a940147c8 "\004", m_tok_start = 0x7f5a940147c8 "\004", m_tok_end = 0x7f5a940147c8 "\004", m_end_of_query = 0x7f5a940147c7 "", m_tok_start_prev = 0x7f5a940147c7 "", m_buf = 0x7f5a940147a8 "ALTER TABLE t IMPORT TABLESPACE", m_buf_length = 31, m_echo = true, m_echo_saved = 12, m_cpp_buf = 0x7f5a94014820 "ALTER TABLE t IMPORT TABLESPACE", m_cpp_ptr = 0x7f5a9401483f "", m_cpp_tok_start = 0x7f5a9401483f "", m_cpp_tok_start_prev = 0x7f5a9401483f "", m_cpp_tok_end = 0x7f5a9401483f "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x56260b8e0a07 <DoTrace+150> "\203\370\005\177\063\205\300\017\210\255", m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_END, found_semicolon = 0x0, ignore_space = false, stmt_prepare_mode = false, multi_statements = true, yylineno = 1, m_digest = 0x0, in_comment = NO_COMMENT, in_comment_saved = (DISCARD_COMMENT | unknown: 0x5624), m_cpp_text_start = 0x7f5a9401482c "t IMPORT TABLESPACE", m_cpp_text_end = 0x7f5a9401482d " IMPORT TABLESPACE", m_underscore_cs = 0x0}, m_yacc = {yacc_yyss = 0x0, yacc_yyvs = 0x0, m_set_signal_info = {m_item = {0x0 <repeats 12 times>}}, m_lock_type = TL_READ_DEFAULT, m_mdl_type = MDL_SHARED_READ}, m_digest_psi = 0x7f5a940046e0}
              net = 0x7f5a940010b8
              error = false
              do_end_of_statement = true
              _db_stack_frame_ = {func = 0x56260b9b0ec5 "do_command", file = 0x56260b9b0cc8 "/data/src/10.4/sql/sql_parse.cc", level = 2147483650, line = -1, prev = 0x7f5ae5fdacb0}
              drop_more_results = false
              __PRETTY_FUNCTION__ = "bool dispatch_command(enum_server_command, THD*, char*, uint, bool, bool)"
              __FUNCTION__ = "dispatch_command"
              res = <optimized out>
      #16 0x000056260acb6c4d in do_command (thd=0x7f5a94000d90) at /data/src/10.4/sql/sql_parse.cc:1378
              return_value = false
              packet = 0x7f5a9400ac00 "\003ALTER TABLE t IMPORT TABLESPACE"
              packet_length = 32
              net = 0x7f5a940010b8
              command = COM_QUERY
              _db_stack_frame_ = {func = 0x56260bd6c368 "?func", file = 0x56260bd6c36e "?file", level = 2147483649, line = -1, prev = 0x0}
              __PRETTY_FUNCTION__ = "bool do_command(THD*)"
              __FUNCTION__ = "do_command"
      #17 0x000056260ae45fbd in do_handle_one_connection (connect=0x56260e24e440) at /data/src/10.4/sql/sql_connect.cc:1420
              create_user = true
              thr_create_utime = 4773826449734
              thd = 0x7f5a94000d90
              __PRETTY_FUNCTION__ = "void do_handle_one_connection(CONNECT*)"
      #18 0x000056260ae45c65 in handle_one_connection (arg=0x56260e24e440) at /data/src/10.4/sql/sql_connect.cc:1316
              connect = 0x56260e24e440
      #19 0x000056260b362f9d in pfs_spawn_thread (arg=0x56260e1a2180) at /data/src/10.4/storage/perfschema/pfs.cc:1869
              typed_arg = 0x56260e1a2180
              user_arg = 0x56260e24e440
              user_start_routine = 0x56260ae45c35 <handle_one_connection(void*)>
              pfs = 0x7f5aef156b40
              klass = 0x56260dc7ac00
      #20 0x00007f5af1321ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
              ret = <optimized out>
              pd = <optimized out>
              unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140028382394112, -738925536457634580, 140723130171934, 140723130171935, 140028382391936, 311296, 795735088686583020, 795779544398187756}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
              not_first_call = 0
      #21 0x00007f5af0f1edef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      On 10.3 the same test case variation causes a different assertion failure:

      10.3 18488048

      2022-07-21 00:16:41 0x7fefbfe69700  InnoDB: Assertion failure in file /data/src/10.3/storage/innobase/dict/dict0dict.cc line 1802
      InnoDB: Failing assertion: table->get_ref_count() == 0
       
      #6  0x0000565287c1b0ea in ut_dbg_assertion_failed (expr=0x565288352506 "table->get_ref_count() == 0", file=0x5652883526a0 "/data/src/10.3/storage/innobase/dict/dict0dict.cc", line=1802) at /data/src/10.3/storage/innobase/ut/ut0dbg.cc:60
      #7  0x0000565287cf5481 in dict_table_remove_from_cache_low (table=0x7fef6c1902e0, lru_evict=0) at /data/src/10.3/storage/innobase/dict/dict0dict.cc:1802
      #8  0x0000565287cf5ea5 in dict_table_remove_from_cache (table=0x7fef6c1902e0) at /data/src/10.3/storage/innobase/dict/dict0dict.cc:1906
      #9  0x00005652879a37f7 in ha_innobase::discard_or_import_tablespace (this=0x7fef7002d548, discard=0 '\000') at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:13164
      #10 0x000056528776fda7 in handler::ha_discard_or_import_tablespace (this=0x7fef7002d548, discard=0 '\000') at /data/src/10.3/sql/handler.cc:4587
      #11 0x0000565287522265 in mysql_discard_or_import_tablespace (thd=0x7fef6c000d90, table_list=0x7fef6c012bb8, discard=false) at /data/src/10.3/sql/sql_table.cc:6070
      #12 0x00005652875bdb40 in Sql_cmd_discard_import_tablespace::execute (this=0x7fef6c013220, thd=0x7fef6c000d90) at /data/src/10.3/sql/sql_alter.cc:553
      #13 0x0000565287449bc8 in mysql_execute_command (thd=0x7fef6c000d90) at /data/src/10.3/sql/sql_parse.cc:6075
      #14 0x000056528744f1aa in mysql_parse (thd=0x7fef6c000d90, rawbuf=0x7fef6c012ad8 "ALTER TABLE t IMPORT TABLESPACE", length=31, parser_state=0x7fefbfe685b0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7870
      #15 0x000056528743b9df in dispatch_command (command=COM_QUERY, thd=0x7fef6c000d90, packet=0x7fef6c008f31 "ALTER TABLE t IMPORT TABLESPACE", packet_length=31, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1852
      #16 0x000056528743a39d in do_command (thd=0x7fef6c000d90) at /data/src/10.3/sql/sql_parse.cc:1398
      #17 0x00005652875b7956 in do_handle_one_connection (connect=0x565289905b30) at /data/src/10.3/sql/sql_connect.cc:1403
      #18 0x00005652875b76c1 in handle_one_connection (arg=0x565289905b30) at /data/src/10.3/sql/sql_connect.cc:1308
      #19 0x0000565287f66dd0 in pfs_spawn_thread (arg=0x565289942040) at /data/src/10.3/storage/perfschema/pfs.cc:1869
      #20 0x00007fefcae79ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #21 0x00007fefcada9def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:

                  Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.