[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 - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Duplicate
Affects Version/s: 10.1(EOL), 10.2(EOL), 10.3(EOL), 10.4(EOL)
Fix Version/s: N/A
Component/s: Data Manipulation - Delete, Storage Engine - InnoDB
Labels:
- foreign-keys

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

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

threads
2019-03-14 23:06
26 kB
Elena Stepanova

Issue Links

duplicates

MDEV-16060 InnoDB: Failing assertion: ut_strcmp(index->name, key->name)

Closed

relates to

MDEV-16557 Remove INNOBASE_SHARE::idx_trans_tbl

Closed

Activity

People

Assignee:: Sergey Vojtovich

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2019-03-14 23:08

Updated:: 2019-05-09 08:12

Resolved:: 2019-05-09 08:12

Git Integration

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