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

Assertion `index' failed in ha_innobase::innobase_get_index or locking issues upon concurrent operations with foreign keys

    XMLWordPrintable

    Details

      Description

      Note: Problems described here are similar to the ones in the comment to MDEV-15776, and test cases are somewhat similar too, so they might be closely related.

      The test case below produces different failures on different 10.x versions, but none works quite all right.

      The test case is non-deterministic, run with --repeat=N if it doesn't fail right away. It usually fails for me within 2-3 attempts, but it can vary on different machines in builds.

      Also, run with --nowarnings or with --force, as when the test itself does not fail, it might produce warnings/errors in the error log.

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (pk INT PRIMARY KEY, i INT) ENGINE=InnoDB;
      CREATE VIEW view1 AS SELECT * FROM t1;
       
      --send
        ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (pk) REFERENCES t1 (pk);
       
      --connect (con1,localhost,root,,test)
      --error ER_SP_DOES_NOT_EXIST
      CALL non_existing_sp;
      PREPARE stmt FROM 'INSERT INTO t1 SELECT * FROM t1';
      EXECUTE stmt;
      FLUSH TABLES;
      SET FOREIGN_KEY_CHECKS= OFF;
      ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (i,pk) REFERENCES view1 (i,pk);
       
      --connection default
      --error ER_ERROR_ON_RENAME
      --reap
      --send
        ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (pk) REFERENCES t1 (pk);
       
      --connection con1
      INSERT INTO t1 SELECT * FROM t1;
       
      # Cleanup
      --disconnect con1
      --connection default
      --reap
      DROP VIEW v1;
      DROP TABLE t1;
      

      On 10.2+

      10.2 debug dc2856ad6

      2018-12-22 14:32:32 140222159992576 [ERROR] InnoDB: In ALTER TABLE `test`.`t1` has or is referenced in foreign key constraints which are not compatible with the new table definition.
      2018-12-22 14:32:32 140222159992576 [Note] InnoDB: Foreign Key referenced table test/view1 not found for foreign table test/t1
      2018-12-22 14:32:32 140222159689472 [ERROR] InnoDB indexes are inconsistent with what defined in .frm for table ./test/#sql-6aed_9
      2018-12-22 14:32:32 140222159689472 [ERROR] InnoDB: Table test/#sql-6aed_9 contains 1 indexes inside InnoDB, which is different from the number of indexes 2 defined in the MariaDB  Have you mixed up .frm files from 
      different installations? See http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting.html
       
      mysqld: /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9537: dict_index_t* ha_innobase::innobase_get_index(uint): Assertion `index' failed.
      181222 14:32:32 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007f88097baee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      #8  0x00005596fa82a8af in ha_innobase::innobase_get_index (this=0x7f87ac047058, keynr=1) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9537
      #9  0x00005596fa8338e2 in ha_innobase::info_low (this=0x7f87ac047058, flag=26, is_analyze=false) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:14333
      #10 0x00005596fa833e34 in ha_innobase::info (this=0x7f87ac047058, flag=26) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:14470
      #11 0x00005596fa8238a1 in ha_innobase::open (this=0x7f87ac047058, name=0x7f87ac043c48 "./test/#sql-6aed_9") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:6535
      #12 0x00005596fa51484a in handler::ha_open (this=0x7f87ac047058, table_arg=0x7f87ac046450, name=0x7f87ac043c48 "./test/#sql-6aed_9", mode=2, test_if_locked=18) at /data/src/10.2/sql/handler.cc:2502
      #13 0x00005596fa39b9de in open_table_from_share (thd=0x7f87ac000b00, share=0x7f87ac043718, alias=0x7f87ac011f70 "#mysql50##sql-6aed_9", db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7f87ac046450, is_create_table=false) at /data/src/10.2/sql/table.cc:3347
      #14 0x00005596fa222d11 in open_table (thd=0x7f87ac000b00, table_list=0x7f87ac012068, ot_ctx=0x7f88040474a0) at /data/src/10.2/sql/sql_base.cc:1923
      #15 0x00005596fa22576a in open_and_process_table (thd=0x7f87ac000b00, lex=0x7f87ac004618, tables=0x7f87ac012068, counter=0x7f8804047534, flags=0, prelocking_strategy=0x7f88040475b0, has_prelocking_list=false, ot_ctx=0x7f88040474a0) at /data/src/10.2/sql/sql_base.cc:3451
      #16 0x00005596fa226a55 in open_tables (thd=0x7f87ac000b00, options=..., start=0x7f8804047518, counter=0x7f8804047534, flags=0, prelocking_strategy=0x7f88040475b0) at /data/src/10.2/sql/sql_base.cc:4011
      #17 0x00005596fa228250 in open_and_lock_tables (thd=0x7f87ac000b00, options=..., tables=0x7f87ac011170, derived=true, flags=0, prelocking_strategy=0x7f88040475b0) at /data/src/10.2/sql/sql_base.cc:4767
      #18 0x00005596fa21b28f in open_and_lock_tables (thd=0x7f87ac000b00, tables=0x7f87ac011170, derived=true, flags=0) at /data/src/10.2/sql/sql_base.h:506
      #19 0x00005596fa298803 in mysql_execute_command (thd=0x7f87ac000b00) at /data/src/10.2/sql/sql_parse.cc:4516
      #20 0x00005596fa2a37e7 in mysql_parse (thd=0x7f87ac000b00, rawbuf=0x7f87ac011088 "INSERT INTO t1 SELECT * FROM t1", length=31, parser_state=0x7f8804048200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8014
      #21 0x00005596fa29111f in dispatch_command (command=COM_QUERY, thd=0x7f87ac000b00, packet=0x7f87ac0088a1 "INSERT INTO t1 SELECT * FROM t1", packet_length=31, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1825
      #22 0x00005596fa28fa82 in do_command (thd=0x7f87ac000b00) at /data/src/10.2/sql/sql_parse.cc:1379
      #23 0x00005596fa3e2535 in do_handle_one_connection (connect=0x5596fd8722f0) at /data/src/10.2/sql/sql_connect.cc:1335
      #24 0x00005596fa3e22c2 in handle_one_connection (arg=0x5596fd8722f0) at /data/src/10.2/sql/sql_connect.cc:1241
      #25 0x00005596fa8081fc in pfs_spawn_thread (arg=0x5596fd890c00) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      #26 0x00007f880b276494 in start_thread (arg=0x7f8804049700) at pthread_create.c:333
      #27 0x00007f880987793f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      or

      10.2 dc2856ad6 debug and non-debug

      mysqltest: At line 30: query 'reap' failed: 1813: Tablespace for table '`test`.`#sql-6c0b_9`' exists. Please DISCARD the tablespace before IMPORT
      

      On 10.1

      The test case hangs (stops for a long while) on EXECUTE stmt. The processlist shows

      10.1 9f4a4cb4019

      +----+------+-----------------+------+---------+------+---------------------------------+-------------------------------------------------------------------+----------+
      | Id | User | Host            | db   | Command | Time | State                           | Info                                                              | Progress |
      +----+------+-----------------+------+---------+------+---------------------------------+-------------------------------------------------------------------+----------+
      |  3 | root | localhost       | test | Query   |   36 | Unlocking tables                | ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (pk) REFERENCES t1 (pk) |    0.000 |
      |  4 | root | localhost       | test | Query   |   36 | Waiting for table metadata lock | INSERT INTO t1 SELECT * FROM t1                                   |    0.000 |
      |  5 | root | localhost:36891 | NULL | Query   |    0 | init                            | show processlist                                                  |    0.000 |
      +----+------+-----------------+------+---------+------+---------------------------------+-------------------------------------------------------------------+----------+
      

      The stack trace from the running server is

      Thread 3 (Thread 0x7fc145ca3b00 (LWP 29366)):
      #0  0x00007fc143eff233 in select () from /lib/x86_64-linux-gnu/libc.so.6
      #1  0x00007fc13d36ef30 in os_thread_sleep (tm=20000) at /data/src/10.1/storage/innobase/os/os0thread.cc:283
      #2  0x00007fc13d3eb4c8 in fil_wait_crypt_bg_threads (table=0x7fc12dd815f8) at /data/src/10.1/storage/innobase/row/row0mysql.cc:3313
      #3  0x00007fc13d3ed4c4 in row_drop_table_for_mysql (name=0x7fc145c9dfd0 "test/#sql-7294_3", trx=0x7fc12dc68a78, drop_db=false, create_failed=0, nonatomic=true) at /data/src/10.1/storage/innobase/row/row0mysql.cc:4174
      #4  0x00007fc13d2e59b2 in ha_innodb::delete_table (this=0x7fc12dc462d8, name=0x7fc145c9f790 "./test/#sql-7294_3") at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:12592
      #5  0x000055b87fe634bc in handler::ha_delete_table (this=0x7fc12dc462d8, name=0x7fc145c9f790 "./test/#sql-7294_3") at /data/src/10.1/sql/handler.cc:4317
      #6  0x000055b87fe5e62f in ha_delete_table (thd=0x7fc13a7c7070, table_type=0x7fc143437470, path=0x7fc145c9f790 "./test/#sql-7294_3", db=0x7fc12dc437a8 "test", alias=0x7fc145ca0750 "#sql-7294_3", generate_warning=false) at /data/src/10.1/sql/handler.cc:2385
      #7  0x000055b87fcd2786 in quick_rm_table (thd=0x7fc13a7c7070, base=0x7fc143437470, db=0x7fc12dc437a8 "test", table_name=0x7fc145ca0750 "#sql-7294_3", flags=3, table_path=0x0) at /data/src/10.1/sql/sql_table.cc:2740
      #8  0x000055b87fce39c7 in mysql_alter_table (thd=0x7fc13a7c7070, new_db=0x7fc12dc437a8 "test", new_name=0x0, create_info=0x7fc145ca1300, table_list=0x7fc12dc431b8, alter_info=0x7fc145ca1270, order_num=0, order=0x0, ignore=false) at /data/src/10.1/sql/sql_table.cc:9344
      #9  0x000055b87fd5444d in Sql_cmd_alter_table::execute (this=0x7fc12dc439a8, thd=0x7fc13a7c7070) at /data/src/10.1/sql/sql_alter.cc:330
      #10 0x000055b87fc22de8 in mysql_execute_command (thd=0x7fc13a7c7070) at /data/src/10.1/sql/sql_parse.cc:5700
      #11 0x000055b87fc2768b in mysql_parse (thd=0x7fc13a7c7070, rawbuf=0x7fc12dc43088 "ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (pk) REFERENCES t1 (pk)", length=65, parser_state=0x7fc145ca25e0) at /data/src/10.1/sql/sql_parse.cc:7467
      #12 0x000055b87fc15edc in dispatch_command (command=COM_QUERY, thd=0x7fc13a7c7070, packet=0x7fc13c6c3071 "ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (pk) REFERENCES t1 (pk)", packet_length=65) at /data/src/10.1/sql/sql_parse.cc:1495
      #13 0x000055b87fc14c61 in do_command (thd=0x7fc13a7c7070) at /data/src/10.1/sql/sql_parse.cc:1124
      #14 0x000055b87fd4f988 in do_handle_one_connection (thd_arg=0x7fc13a7c7070) at /data/src/10.1/sql/sql_connect.cc:1330
      #15 0x000055b87fd4f6ec in handle_one_connection (arg=0x7fc13a7c7070) at /data/src/10.1/sql/sql_connect.cc:1242
      #16 0x000055b88010d982 in pfs_spawn_thread (arg=0x7fc13ebf2670) at /data/src/10.1/storage/perfschema/pfs.cc:1861
      #17 0x00007fc145932494 in start_thread (arg=0x7fc145ca3b00) at pthread_create.c:333
      #18 0x00007fc143f0693f in clone () from /lib/x86_64-linux-gnu/libc.so.6
       
      Thread 2 (Thread 0x7fc145c59b00 (LWP 29367)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
      #1  0x000055b8804c2b34 in safe_cond_timedwait (cond=0x7fc13a7cd218, mp=0x7fc13a7cd168, abstime=0x7fc145c56170, file=0x55b8805af980 "/data/src/10.1/include/mysql/psi/mysql_thread.h", line=1191) at /data/src/10.1/mysys/thr_mutex.c:547
      #2  0x000055b87fd588da in inline_mysql_cond_timedwait (that=0x7fc13a7cd218, mutex=0x7fc13a7cd168, abstime=0x7fc145c56170, src_file=0x55b8805afbfa "/data/src/10.1/sql/mdl.cc", src_line=1088) at /data/src/10.1/include/mysql/psi/mysql_thread.h:1191
      #3  0x000055b87fd59c0f in MDL_wait::timed_wait (this=0x7fc13a7cd168, owner=0x7fc13a7cd120, abs_timeout=0x7fc145c56170, set_status_on_timeout=false, wait_state_name=0x55b880d3a4f0 <MDL_key::m_namespace_to_wait_state_name+48>) at /data/src/10.1/sql/mdl.cc:1088
      #4  0x000055b87fd5b744 in MDL_context::acquire_lock (this=0x7fc13a7cd168, mdl_request=0x7fc12e060a90, lock_wait_timeout=31536000) at /data/src/10.1/sql/mdl.cc:2125
      #5  0x000055b87fbb00a6 in open_table_get_mdl_lock (thd=0x7fc13a7cd070, ot_ctx=0x7fc145c56830, mdl_request=0x7fc12e060a90, flags=0, mdl_ticket=0x7fc145c56460) at /data/src/10.1/sql/sql_base.cc:2115
      #6  0x000055b87fbb09a2 in open_table (thd=0x7fc13a7cd070, table_list=0x7fc12e060668, ot_ctx=0x7fc145c56830) at /data/src/10.1/sql/sql_base.cc:2407
      #7  0x000055b87fbb393d in open_and_process_table (thd=0x7fc13a7cd070, lex=0x7fc12e05f090, tables=0x7fc12e060668, counter=0x7fc145c568c4, flags=0, prelocking_strategy=0x7fc145c56940, has_prelocking_list=true, ot_ctx=0x7fc145c56830) at /data/src/10.1/sql/sql_base.cc:4124
      #8  0x000055b87fbb49dd in open_tables (thd=0x7fc13a7cd070, options=..., start=0x7fc145c568a8, counter=0x7fc145c568c4, flags=0, prelocking_strategy=0x7fc145c56940) at /data/src/10.1/sql/sql_base.cc:4639
      #9  0x000055b87fbb60d6 in open_and_lock_tables (thd=0x7fc13a7cd070, options=..., tables=0x7fc12e060668, derived=true, flags=0, prelocking_strategy=0x7fc145c56940) at /data/src/10.1/sql/sql_base.cc:5385
      #10 0x000055b87fba9377 in open_and_lock_tables (thd=0x7fc13a7cd070, tables=0x7fc12e060668, derived=true, flags=0) at /data/src/10.1/sql/sql_base.h:544
      #11 0x000055b87fc1cd02 in mysql_execute_command (thd=0x7fc13a7cd070) at /data/src/10.1/sql/sql_parse.cc:4012
      #12 0x000055b87fc41e0f in Prepared_statement::execute (this=0x7fc12e04f470, expanded_query=0x7fc145c579e0, open_cursor=false) at /data/src/10.1/sql/sql_prepare.cc:4322
      #13 0x000055b87fc40c75 in Prepared_statement::execute_loop (this=0x7fc12e04f470, expanded_query=0x7fc145c579e0, open_cursor=false, packet=0x0, packet_end=0x0) at /data/src/10.1/sql/sql_prepare.cc:3954
      #14 0x000055b87fc3ecaa in mysql_sql_stmt_execute (thd=0x7fc13a7cd070) at /data/src/10.1/sql/sql_prepare.cc:3070
      #15 0x000055b87fc19e4d in mysql_execute_command (thd=0x7fc13a7cd070) at /data/src/10.1/sql/sql_parse.cc:3005
      #16 0x000055b87fc2768b in mysql_parse (thd=0x7fc13a7cd070, rawbuf=0x7fc12e022088 "EXECUTE stmt", length=12, parser_state=0x7fc145c585e0) at /data/src/10.1/sql/sql_parse.cc:7467
      #17 0x000055b87fc15edc in dispatch_command (command=COM_QUERY, thd=0x7fc13a7cd070, packet=0x7fc13a7d9071 "EXECUTE stmt", packet_length=12) at /data/src/10.1/sql/sql_parse.cc:1495
      #18 0x000055b87fc14c61 in do_command (thd=0x7fc13a7cd070) at /data/src/10.1/sql/sql_parse.cc:1124
      #19 0x000055b87fd4f988 in do_handle_one_connection (thd_arg=0x7fc13a7cd070) at /data/src/10.1/sql/sql_connect.cc:1330
      #20 0x000055b87fd4f6ec in handle_one_connection (arg=0x7fc13a7cd070) at /data/src/10.1/sql/sql_connect.cc:1242
      #21 0x000055b88010d982 in pfs_spawn_thread (arg=0x7fc13ebf2b70) at /data/src/10.1/storage/perfschema/pfs.cc:1861
      #22 0x00007fc145932494 in start_thread (arg=0x7fc145c59b00) at pthread_create.c:333
      #23 0x00007fc143f0693f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      It doesn't hang forever, it gives up after 300 seconds. I don't know where this timeout comes from, it's neither lock_wait_timeout nor innodb_lock_wait_timeout.

      On 10.0

      10.0 8634f7e528

      mysqltest: At line 30: query 'reap' failed: 1813: Tablespace for table '`test`.`#sql-73dd_3`' exists. Please DISCARD the tablespace before IMPORT.
      

      and sometimes also

      INSERT INTO t1 SELECT * FROM t1;
      Warnings:
      Warning	1082	InnoDB: Table test/#sql-73dd_3 contains 1 indexes inside InnoDB, which is different from the number of indexes 2 defined in the MySQL 
      Warning	1082	InnoDB: Table test/#sql-73dd_3 contains 1 indexes inside InnoDB, which is different from the number of indexes 2 defined in the MySQL 
      

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated: