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

Hang on shutdown in rec_get_next_offs or Failing assertion: share->idx_trans_tbl.index_count == mysql_num_index in innobase_build_index_translation

    XMLWordPrintable

Details

    Description

      Run with --repeat=N if problems don't start right away.

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (f1 INT, f2 DECIMAL) ENGINE=InnoDB;
      CREATE TABLE t2 (f3 BIT, UNIQUE(f3)) ENGINE=InnoDB;
      CREATE TABLE t3 (f4 INT) ENGINE=InnoDB;
       
      --connect (con1,localhost,root,,test)
      --send
        ALTER TABLE t1 ADD FOREIGN KEY (f2) REFERENCES t2 (f3);
       
      --connect (con2,localhost,root,,test)
      --error ER_NO_SUCH_TABLE
      ALTER TABLE x DROP xx;
      --send
        ALTER TABLE t2 DROP FOREIGN KEY x;
       
      --connection default
      DELETE FROM t2;
       
      --connection con1
      --reap
      ALTER TABLE t3 ENGINE=InnoDB, ALGORITHM=COPY;
       
      --connection con2
      --error ER_CANT_DROP_FIELD_OR_KEY
      --reap
       
      # Cleanup
      --disconnect con2
      --disconnect con1
      --connection default
      DROP TABLE t1, t2, t3;
      

      The test case above causes an assertion failure on 10.1 (both debug and non-debug) and seemingly infinite loop on shutdown on 10.2-10.4 (both debug and non-debug).

      10.4 3568427d Hang on shutdown

      Thread 11 (Thread 0x7f0aa8ff9700 (LWP 18222)):
      #0  0x00007f0ac05131c0 in __pthread_mutex_unlock_usercnt (mutex=0x7f0aa8ff8058, decr=<optimized out>) at pthread_mutex_unlock.c:55
      #1  0x0000556bc3fc4c86 in OSMutex::exit (this=0x7f0aa8ff8050) at /data/src/10.4/storage/innobase/include/sync0types.h:442
      #2  0x0000556bc3fcce47 in MutexDebug<TTASEventMutex<GenericPolicy> >::set (this=0x7f0aa8ff8020, mutex=0x0, filename=0x0, line=0, thread_id=18446744073709551615) at /data/src/10.4/storage/innobase/include/sync0policy.h:59
      #3  0x0000556bc3fcba59 in MutexDebug<TTASEventMutex<GenericPolicy> >::enter (this=0x7f0ab8649280, mutex=..., filename=0x556bc47b1d50 "/data/src/10.4/storage/innobase/que/que0que.cc", line=615) at /data/src/10.4/storage/innobase/include/sync0policy.h:126
      #4  0x0000556bc3fc9dbd in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x7f0ab8649270, n_spins=30, n_delay=4, name=0x556bc47b1d50 "/data/src/10.4/storage/innobase/que/que0que.cc", line=615) at /data/src/10.4/storage/innobase/include/ib0mutex.h:593
      #5  0x0000556bc40b5647 in que_thr_node_step (thr=0x7f0a7c002400) at /data/src/10.4/storage/innobase/que/que0que.cc:615
      #6  0x0000556bc40b64a6 in que_thr_step (thr=0x7f0a7c002400) at /data/src/10.4/storage/innobase/que/que0que.cc:1036
      #7  0x0000556bc40b672d in que_run_threads_low (thr=0x7f0a7c002400) at /data/src/10.4/storage/innobase/que/que0que.cc:1104
      #8  0x0000556bc40b691e in que_run_threads (thr=0x7f0a7c002400) at /data/src/10.4/storage/innobase/que/que0que.cc:1144
      #9  0x0000556bc40b6bcb in que_eval_sql (info=0x7f0a7c000c98, sql=0x556bc4870d00 "PROCEDURE DELETE_FROM_TABLE_STATS () IS\nBEGIN\nDELETE FROM \"mysql/innodb_table_stats\" WHERE\ndatabase_name = :database_name AND\ntable_name = :table_name;\nEND;\n", reserve_dict_mutex=0, trx=0x7f0ab8649268) at /data/src/10.4/storage/innobase/que/que0que.cc:1221
      #10 0x0000556bc42b2a90 in dict_stats_exec_sql (pinfo=0x7f0a7c000c98, sql=0x556bc4870d00 "PROCEDURE DELETE_FROM_TABLE_STATS () IS\nBEGIN\nDELETE FROM \"mysql/innodb_table_stats\" WHERE\ndatabase_name = :database_name AND\ntable_name = :table_name;\nEND;\n", trx=0x7f0ab8649268) at /data/src/10.4/storage/innobase/dict/dict0stats.cc:305
      #11 0x0000556bc42b9ba3 in dict_stats_delete_from_table_stats (database_name=0x7f0aa8ff8320 "test", table_name=0x7f0aa8ff83f0 "#mysql50##sql-ib23") at /data/src/10.4/storage/innobase/dict/dict0stats.cc:3486
      #12 0x0000556bc42b9e46 in dict_stats_drop_table (db_and_table=0x7f0a68009fa0 "test/#sql-ib23", errstr=0x7f0aa8ff89d0 "", errstr_sz=1024) at /data/src/10.4/storage/innobase/dict/dict0stats.cc:3564
      #13 0x0000556bc411593e in row_drop_table_for_mysql (name=0x7f0a68009fa0 "test/#sql-ib23", trx=0x7f0ab8648140, sqlcom=SQLCOM_TRUNCATE, create_failed=false, nonatomic=true) at /data/src/10.4/storage/innobase/row/row0mysql.cc:3465
      #14 0x0000556bc41138d9 in row_drop_table_for_mysql_in_background (name=0x7f0a68009fa0 "test/#sql-ib23") at /data/src/10.4/storage/innobase/row/row0mysql.cc:2625
      #15 0x0000556bc4113bb9 in row_drop_tables_for_mysql_in_background () at /data/src/10.4/storage/innobase/row/row0mysql.cc:2693
      #16 0x0000556bc4173518 in srv_master_do_active_tasks () at /data/src/10.4/storage/innobase/srv/srv0srv.cc:2125
      #17 0x0000556bc41741a5 in srv_master_thread (arg=0x0) at /data/src/10.4/storage/innobase/srv/srv0srv.cc:2356
      #18 0x00007f0ac050f494 in start_thread (arg=0x7f0aa8ff9700) at pthread_create.c:333
      #19 0x00007f0abe8f593f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      Thread 3 (Thread 0x7f0a98ff9700 (LWP 18230)):
      #0  0x0000556bc3fc4aba in OSMutex::init (this=0x7f0a98ff8c60) at /data/src/10.4/storage/innobase/include/sync0types.h:402
      #1  0x0000556bc3fccdb9 in MutexDebug<TTASEventMutex<GenericPolicy> >::init (this=0x7f0a98ff8c30, id=LATCH_ID_SRV_SYS) at /data/src/10.4/storage/innoba
      se/include/sync0policy.h:99
      #2  0x0000556bc3fcba00 in MutexDebug<TTASEventMutex<GenericPolicy> >::enter (this=0x556bc4fe0888 <srv_sys+200>, mutex=..., filename=0x556bc47fd060 "/d
      ata/src/10.4/storage/innobase/srv/srv0srv.cc", line=929) at /data/src/10.4/storage/innobase/include/sync0policy.h:122
      #3  0x0000556bc3fc9dbd in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x556bc4fe0878 <srv_sys+184>, n_spins=30, n_delay=4, name=0x556bc47
      fd060 "/data/src/10.4/storage/innobase/srv/srv0srv.cc", line=929) at /data/src/10.4/storage/innobase/include/ib0mutex.h:593
      #4  0x0000556bc4170b6c in srv_release_threads (type=SRV_MASTER, n=1) at /data/src/10.4/storage/innobase/srv/srv0srv.cc:929
      #5  0x0000556bc4173019 in srv_wake_master_thread () at /data/src/10.4/storage/innobase/srv/srv0srv.cc:1942
      #6  0x0000556bc417cca9 in srv_shutdown_bg_undo_sources () at /data/src/10.4/storage/innobase/srv/srv0start.cc:2426
      #7  0x0000556bc3f9cf26 in thd_destructor_proxy () at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:308
      #8  0x0000556bc3f89a89 in pfs_spawn_thread (arg=0x556bc67411b0) at /data/src/10.4/storage/perfschema/pfs.cc:1862
      #9  0x00007f0ac050f494 in start_thread (arg=0x7f0a98ff9700) at pthread_create.c:333
      #10 0x00007f0abe8f593f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      error log

      2019-03-15  1:03:36 9 [Note] InnoDB: Deferring DROP TABLE `test`.`t1`; renaming to test/#sql-ib23
      2019-03-15  1:03:36 0 [Note] /data/bld/10.4/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
      2019-03-15  1:03:36 0 [Note] InnoDB: FTS optimize thread exiting.
      2019-03-15  1:03:36 0 [Note] Event Scheduler: Purging the queue. 0 events
      2019-03-15  1:03:57 0 [Warning] /data/bld/10.4/bin/mysqld: Thread 5 (user : '') did not exit
       
      2019-03-15  1:03:57 0 [Warning] /data/bld/10.4/bin/mysqld: Thread 3 (user : '') did not exit
       
      2019-03-15  1:03:57 0 [Warning] /data/bld/10.4/bin/mysqld: Thread 2 (user : '') did not exit
       
      2019-03-15  1:03:57 0 [Warning] /data/bld/10.4/bin/mysqld: Thread 4 (user : '') did not exit
       
      2019-03-15  1:03:57 0 [Warning] /data/bld/10.4/bin/mysqld: Thread 1 (user : '') did not exit
      

      All threads are attached as threads.
      The server wildly consumes CPU.

      10.1 3b2a5685

      2019-03-15 01:07:29 7fd4cd88e700  InnoDB: Assertion failure in thread 140551958095616 in file ha_innodb.cc line 5558
      InnoDB: Failing assertion: share->idx_trans_tbl.index_count == mysql_num_index
       
      #5  0x00007fd4cb86c3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
      #6  0x00007fd4c4ee9ef6 in innobase_build_index_translation (table=0x7fd4b5cca070, ib_table=0x7fd4b5c46d78, share=0x7fd4b5c46af0) at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:5558
      #7  0x00007fd4c4eeadf5 in ha_innodb::open (this=0x7fd4b5c50088, name=0x7fd4b5ccb0e8 "./test/#sql-4831_4", mode=2, test_if_locked=18) at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:6052
      #8  0x000055622830fe82 in handler::ha_open (this=0x7fd4b5c50088, table_arg=0x7fd4b5cca070, name=0x7fd4b5ccb0e8 "./test/#sql-4831_4", mode=2, test_if_locked=18) at /data/src/10.1/sql/handler.cc:2534
      #9  0x00005562281bdc70 in open_table_from_share (thd=0x7fd4c23cd070, share=0x7fd4b5ccac18, alias=0x7fd4cd88b350 "#sql-4831_4", db_stat=7, prgflag=44, ha_open_flags=18, outparam=0x7fd4b5cca070, is_create_table=false) at /data/src/10.1/sql/table.cc:2975
      #10 0x000055622806718f in open_table_uncached (thd=0x7fd4c23cd070, hton=0x7fd4cb037470, frm=0x7fd4cd88a5f0, path=0x7fd4cd88bbbc "./test/#sql-4831_4", db=0x7fd4b5c22780 "test", table_name=0x7fd4cd88b350 "#sql-4831_4", add_to_temporary_tables_list=true, open_in_engine=true) at /data/src/10.1/sql/sql_base.cc:5857
      #11 0x000055622819360d in mysql_alter_table (thd=0x7fd4c23cd070, new_db=0x7fd4b5c22780 "test", new_name=0x0, create_info=0x7fd4cd88bf00, table_list=0x7fd4b5c22190, alter_info=0x7fd4cd88be70, order_num=0, order=0x0, ignore=false) at /data/src/10.1/sql/sql_table.cc:9126
      #12 0x0000556228204f35 in Sql_cmd_alter_table::execute (this=0x7fd4b5c22798, thd=0x7fd4c23cd070) at /data/src/10.1/sql/sql_alter.cc:328
      #13 0x00005562280d2e58 in mysql_execute_command (thd=0x7fd4c23cd070) at /data/src/10.1/sql/sql_parse.cc:5687
      #14 0x00005562280d7713 in mysql_parse (thd=0x7fd4c23cd070, rawbuf=0x7fd4b5c22088 "ALTER TABLE t3 ENGINE=InnoDB, ALGORITHM=COPY", length=44, parser_state=0x7fd4cd88d1e0) at /data/src/10.1/sql/sql_parse.cc:7454
      #15 0x00005562280c60f3 in dispatch_command (command=COM_QUERY, thd=0x7fd4c23cd070, packet=0x7fd4c23d3071 "ALTER TABLE t3 ENGINE=InnoDB, ALGORITHM=COPY", packet_length=44) at /data/src/10.1/sql/sql_parse.cc:1498
      #16 0x00005562280c4e7e in do_command (thd=0x7fd4c23cd070) at /data/src/10.1/sql/sql_parse.cc:1130
      #17 0x000055622820048c in do_handle_one_connection (thd_arg=0x7fd4c23cd070) at /data/src/10.1/sql/sql_connect.cc:1330
      #18 0x00005562282001f0 in handle_one_connection (arg=0x7fd4c23cd070) at /data/src/10.1/sql/sql_connect.cc:1242
      #19 0x00005562285bec22 in pfs_spawn_thread (arg=0x7fd4c67eab70) at /data/src/10.1/storage/perfschema/pfs.cc:1861
      #20 0x00007fd4cd567494 in start_thread (arg=0x7fd4cd88e700) at pthread_create.c:333
      #21 0x00007fd4cb92093f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      Please note that the MTR test won't hang, MTR will kill the server after MTR_SHUTDOWN_TIMEOUT seconds (10 seconds by default). You can see the signs of the hang if execution stops for this long after DROP TABLE; also, the server error log afterwards will show the start of shutdown, but not the end of it. You can also increase the timeout, e.g. run the test as

      MTR_SHUTDOWN_TIMEOUT=60 perl ./mtr ...
      

      Another way to spot the problem, without relying on the timing observations, is to try to re-create the table after DROP (same test case, with two extra lines at the end:

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (f1 INT, f2 DECIMAL) ENGINE=InnoDB;
      CREATE TABLE t2 (f3 BIT, UNIQUE(f3)) ENGINE=InnoDB;
      CREATE TABLE t3 (f4 INT) ENGINE=InnoDB;
       
      --connect (con1,localhost,root,,test)
      --send
        ALTER TABLE t1 ADD FOREIGN KEY (f2) REFERENCES t2 (f3);
       
      --connect (con2,localhost,root,,test)
      --error ER_NO_SUCH_TABLE
      ALTER TABLE x DROP xx;
      --send
        ALTER TABLE t2 DROP FOREIGN KEY x;
       
      --connection default
      DELETE FROM t2;
       
      --connection con1
      --reap
      ALTER TABLE t3 ENGINE=InnoDB, ALGORITHM=COPY;
       
      --connection con2
      --error ER_CANT_DROP_FIELD_OR_KEY
      --reap
       
      # Cleanup
      --disconnect con2
      --disconnect con1
      --connection default
      DROP TABLE t1, t2, t3;
       
      CREATE TABLE t1 (x INT) ENGINE=InnoDB;
      DROP TABLE IF EXISTS t1;
      

      10.2 e63f6216

      mysqltest: At line 34: query 'CREATE TABLE t1 (x INT) ENGINE=InnoDB' failed: 1005: Can't create table `test`.`t1` (errno: 150 "Foreign key constraint is incorrectly formed")
      

      Attachments

        1. threads
          26 kB
          Elena Stepanova

        Issue Links

          Activity

            People

              svoj Sergey Vojtovich
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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