|
For me, the hung DROP TABLE is waiting for dict_table_t::n_ref_count of test.t1 to become 0, but it is 1:
|
10.2 31c950cca8fa1623d41a8a7784e09fbcd6bc2c71
|
#2 0x000056432f1c27fb in fil_wait_crypt_bg_threads (table=0x7fae0001e678)
|
at /mariadb/10.3/storage/innobase/row/row0mysql.cc:3176
|
#3 0x000056432f1c39dc in row_drop_table_for_mysql (
|
name=0x7fae66d36780 "test/t1", trx=0x7fae679027e8, drop_db=false,
|
create_failed=0, nonatomic=true)
|
at /mariadb/10.3/storage/innobase/row/row0mysql.cc:3573
|
#4 0x000056432f08df98 in ha_innobase::delete_table (this=0x7fadfc012ff0,
|
name=0x7fae66d382c0 "./test/t1")
|
at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:13348
|
I did not find any thread that would be holding a handle to the table. Possibly we forgot to decrement the n_ref_count somewhere. The following instrumentation
diff --git a/storage/innobase/include/dict0dict.ic b/storage/innobase/include/dict0dict.ic
|
index ca2ea769612..d079b03e792 100644
|
--- a/storage/innobase/include/dict0dict.ic
|
+++ b/storage/innobase/include/dict0dict.ic
|
@@ -1514,6 +1514,8 @@ void
|
dict_table_t::acquire()
|
{
|
ut_ad(mutex_own(&dict_sys->mutex));
|
+ if (!strcmp(name.m_name, "test/t1"))
|
+ fprintf(stderr, "acquire %p\n", this);
|
++n_ref_count;
|
}
|
|
@@ -1525,6 +1527,8 @@ dict_table_t::release()
|
{
|
ut_ad(mutex_own(&dict_sys->mutex));
|
ut_ad(n_ref_count > 0);
|
+ if (!strcmp(name.m_name, "test/t1"))
|
+ fprintf(stderr, "release %p\n", this);
|
return !--n_ref_count;
|
}
|
|
produced this output:
Version: '10.2.17-MariaDB-debug-log' socket: '/dev/shm/10.2/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution
|
acquire 0x7fd6a006eb68
|
release 0x7fd6a006eb68
|
acquire 0x7fd6a006eb68
|
release 0x7fd6a006eb68
|
acquire 0x7fd6a006eb68
|
release 0x7fd6a006eb68
|
acquire 0x7fd6a006eb68
|
acquire 0x7fd6a006eb68
|
2018-06-26 19:46:58 140561600452352 [ERROR] Invalid (old?) table or database name '#sql-bb8_a'
|
release 0x7fd6a006eb68
|
release 0x7fd6a006eb68
|
acquire 0x7fd6a006eb68
|
release 0x7fd6a401d148
|
acquire 0x7fd6a401d148
|
release 0x7fd6a401d148
|
The table object 0x7fd6a006eb68 was freed. For the table 0x7fd6a401d148, we for some reason got n_ref_count=1. I should improve the instrumentation to catch all acquire and release on that object, no matter what the table name was.
|
|
When the test fails, I am observing an increment of the reference count from 1 to 2 that comes from a stray write (not dict_table_t::acquire(). Once I got it during __lll_lock_wait() (unfortunately no stack trace), and twice so far with this stack:
#0 0x0000555556507d91 in _db_enter_ (_func_=0x5555568636b1 "unpack_dirname",
|
_file_=0x555556863642 "mysys/mf_pack.c", _line_=338,
|
_stack_frame_=0x7ffff07675f0) at dbug/dbug.c:1101
|
#1 0x00005555564cb13d in unpack_dirname (to=0x7ffff0767890 "././test/",
|
from=0x7ffff0767890 "././test/") at mysys/mf_pack.c:338
|
#2 0x00005555564cb46d in unpack_filename (
|
to=0x7ffff0767b80 "././test/#sql-4bdf_9.frm",
|
from=0x7ffff0767b80 "././test/#sql-4bdf_9.frm")
|
at mysys/mf_pack.c:421
|
#3 0x0000555555f9f0cd in ha_innobase::info_low (this=0x7fff88026cf8,
|
flag=26, is_analyze=false)
|
at storage/innobase/handler/ha_innodb.cc:14493
|
#4 0x0000555555f9f342 in ha_innobase::info (this=0x7fff88026cf8, flag=26)
|
at storage/innobase/handler/ha_innodb.cc:14549
|
#5 0x0000555555f8e2f4 in ha_innobase::open (this=0x7fff88026cf8,
|
name=0x7fff8801f8f8 "./test/#sql-4bdf_9")
|
at storage/innobase/handler/ha_innodb.cc:6643
|
#6 0x0000555555d88130 in handler::ha_open (this=0x7fff88026cf8,
|
table_arg=0x7fff880260f0, name=0x7fff8801f8f8 "./test/#sql-4bdf_9",
|
mode=2, test_if_locked=18) at sql/handler.cc:2501
|
#7 0x0000555555c14e9a in open_table_from_share (thd=0x7fff88000e00,
|
share=0x7fff8801f3e0, alias=0x7ffff076a240 "#sql-4bdf_9", db_stat=1,
|
prgflag=8, ha_open_flags=18, outparam=0x7fff880260f0,
|
is_create_table=false) at sql/table.cc:3334
|
#8 0x0000555555d03961 in THD::open_temporary_table (this=0x7fff88000e00,
|
share=0x7fff8801f3e0, alias=0x7ffff076a240 "#sql-4bdf_9",
|
open_in_engine=true) at sql/temporary_tables.cc:1102
|
#9 0x0000555555d01976 in THD::create_and_open_tmp_table (
|
this=0x7fff88000e00, hton=0x555557ad6610, frm=0x7ffff07695a0,
|
path=0x7ffff076aaac "./test/#sql-4bdf_9", db=0x7fff88011b40 "test",
|
table_name=0x7ffff076a240 "#sql-4bdf_9", open_in_engine=true)
|
at sql/temporary_tables.cc:76
|
#10 0x0000555555be66bf in mysql_alter_table (thd=0x7fff88000e00,
|
new_db=0x7fff88011b40 "test", new_name=0x0, create_info=0x7ffff076ae20,
|
table_list=0x7fff88011530, alter_info=0x7ffff076ad70, order_num=0,
|
order=0x0, ignore=false) at sql/sql_table.cc:9487
|
#11 0x0000555555c5fdbe in Sql_cmd_alter_table::execute (this=0x7fff88011d40,
|
thd=0x7fff88000e00) at sql/sql_alter.cc:318
|
#12 0x0000555555b19cd8 in mysql_execute_command (thd=0x7fff88000e00)
|
at sql/sql_parse.cc:6223
|
#13 0x0000555555b1ed7a in mysql_parse (thd=0x7fff88000e00,
|
rawbuf=0x7fff880113b8 "ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (a) REFERENCES t2(b) ON DELETE CASCADE ON UPDATE CASCADE", length=98,
|
parser_state=0x7ffff076c1e0, is_com_multi=false, is_next_command=false)
|
at sql/sql_parse.cc:8000
|
void _db_enter_(const char *_func_, const char *_file_,
|
uint _line_, struct _db_stack_frame_ *_stack_frame_)
|
{
|
int save_errno, org_cs_locked;
|
CODE_STATE *cs;
|
if (!((cs=code_state())))
|
0x0000555556507d88 <+24>: callq 0x5555565059c9 <code_state>
|
0x0000555556507d8d <+29>: mov %rax,-0x18(%rbp)
|
=> 0x0000555556507d91 <+33>: cmpq $0x0,-0x18(%rbp)
|
This looks strange, because the code appears to be accessing the local stack frame, and %rbp is nowhere close to the n_ref_count.
I recompiled cmake -DWITH_ASAN:BOOL=ON, and the behaviour remained mostly the same. I also got a more plausible stack trace:
#0 dict_table_t::acquire (this=0x617000040288)
|
at storage/innobase/include/dict0dict.ic:1519
|
#1 0x00005555575b10b6 in dict_table_open_on_name (
|
table_name=0x7fffdec9e6b0 "test/#sql-588b_9", dict_locked=0, try_drop=1,
|
ignore_err=DICT_ERR_IGNORE_NONE)
|
at storage/innobase/dict/dict0dict.cc:1212
|
#2 0x0000555556f4ec3f in ha_innobase::open_dict_table (
|
table_name=0x61b000079228 "./test/#sql-588b_9",
|
norm_name=0x7fffdec9e6b0 "test/#sql-588b_9", is_partition=false,
|
ignore_err=DICT_ERR_IGNORE_NONE)
|
at storage/innobase/handler/ha_innodb.cc:6681
|
#3 0x0000555556f4bf6f in ha_innobase::open (this=0x61d000170308,
|
name=0x61b000079228 "./test/#sql-588b_9")
|
at storage/innobase/handler/ha_innodb.cc:6341
|
#4 0x00005555569f73b5 in handler::ha_open (this=0x61d000170308,
|
table_arg=0x61f0000444f0, name=0x61b000079228 "./test/#sql-588b_9",
|
mode=2, test_if_locked=18) at sql/handler.cc:2501
|
#5 0x0000555556672a78 in open_table_from_share (thd=0x62a0000ae270,
|
share=0x61b000078d08, alias=0x62b000000d30 "#mysql50##sql-588b_9",
|
db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x61f0000444f0,
|
is_create_table=false) at sql/table.cc:3334
|
#6 0x00005555562816de in open_table (thd=0x62a0000ae270,
|
table_list=0x62b000000e28, ot_ctx=0x7fffdec9f8b0)
|
at sql/sql_base.cc:1885
|
#7 0x0000555556288499 in open_and_process_table (thd=0x62a0000ae270,
|
lex=0x62a0000b1d80, tables=0x62b000000e28, counter=0x7fffdec9fc10,
|
flags=0, prelocking_strategy=0x7fffdec9f990, has_prelocking_list=false,
|
ot_ctx=0x7fffdec9f8b0) at sql/sql_base.cc:3404
|
#8 0x000055555628b678 in open_tables (thd=0x62a0000ae270, options=...,
|
start=0x7fffdec9fa60, counter=0x7fffdec9fc10, flags=0,
|
prelocking_strategy=0x7fffdec9f990) at sql/sql_base.cc:3958
|
#9 0x000055555633f8c9 in open_tables (thd=0x62a0000ae270,
|
tables=0x7fffdec9fa60, counter=0x7fffdec9fc10, flags=0)
|
at sql/sql_base.h:470
|
#10 0x000055555662e24f in mysql_update (thd=0x62a0000ae270,
|
table_list=0x62b000000360, fields=..., values=..., conds=0x0,
|
order_num=0, order=0x0, limit=18446744073709551615,
|
handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7fffdeca0a30,
|
updated_return=0x7fffdeca0a70) at sql/sql_update.cc:286
|
#11 0x00005555563af225 in mysql_execute_command (thd=0x62a0000ae270)
|
at sql/sql_parse.cc:4280
|
#12 0x00005555563cab19 in mysql_parse (thd=0x62a0000ae270,
|
rawbuf=0x62b000000288 "UPDATE t2 SET b = 1", length=19,
|
parser_state=0x7fffdeca3c40, is_com_multi=false, is_next_command=false)
|
at sql/sql_parse.cc:8000
|
In this stack trace, the UPDATE t2 is for some reason opening the intermediate copy of the table t1 where a connection to t2 is being added:
ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (a) REFERENCES t2(b) ON DELETE CASCADE ON UPDATE CASCADE;
|
At this point, the only foreign key metadata that is attached to the intermediate table is foreign_set with 1 element:
(gdb) p **foreign_set.begin()
|
$4 = {heap = 0x611000050b80, id = 0x61600004ff78 "test/#sql-588b_9_ibfk_1",
|
n_fields = 1, type = 5,
|
foreign_table_name = 0x61600004ffa0 "test/#sql-588b_9",
|
foreign_table_name_lookup = 0x61600004ffa0 "test/#sql-588b_9",
|
foreign_table = 0x617000040288, foreign_col_names = 0x61600004ffb8,
|
referenced_table_name = 0x61600004ffc8 "test/t2",
|
referenced_table_name_lookup = 0x61600004ffc8 "test/t2",
|
referenced_table = 0x617000032288, referenced_col_names = 0x61600004ffd0,
|
foreign_index = 0x618000050d08, referenced_index = 0x618000040d08,
|
v_cols = 0x0}
|
mysql_update() comes up with a table_list of 2 elements: t2 and the intermediate (uncommitted) copy of the table t1.
DBUG_ENTER("mysql_update");
|
|
create_explain_query(thd->lex, thd->mem_root);
|
if (open_tables(thd, &table_list, &table_count, 0))
|
DBUG_RETURN(1);
|
We should ensure that FOREIGN KEY relationships are not exposed to the SQL layer before the completion of the ALTER TABLE.
|
|
The UPDATE t2 will find the intermediate copy of t1, because the ALTER TABLE would register it in t2:
(gdb) p **referenced_set.begin()
|
$20 = {heap = 0x611000050b80, id = 0x61600004ff78 "test/#sql-588b_9_ibfk_1",
|
n_fields = 1, type = 5,
|
foreign_table_name = 0x61600004ffa0 "test/#sql-588b_9",
|
foreign_table_name_lookup = 0x61600004ffa0 "test/#sql-588b_9",
|
foreign_table = 0x617000040288, foreign_col_names = 0x61600004ffb8,
|
referenced_table_name = 0x61600004ffc8 "test/t2",
|
referenced_table_name_lookup = 0x61600004ffc8 "test/t2",
|
referenced_table = 0x617000032288, referenced_col_names = 0x61600004ffd0,
|
foreign_index = 0x618000050d08, referenced_index = 0x618000040d08,
|
v_cols = 0x0}
|
svoj pointed out that the ALTER TABLE should prevent writes on t2 for the duration of the ALGORITHM=COPY operation, just like it read-locks t1, not only because the being-added FOREIGN KEY constraint could be violated by concurrent modifications to the related tables, but also because concurrent modifications would require CASCADE modifications on the ALTER TABLE (and InnoDB would fail to perform these modifications, because the foreign key relationship was not recorded in dict_table_t::foreign_list or dict_table_t::referenced_list yet.
So, it seems to me that the fix should be to acquire MDL on all connected tables during ALTER TABLE when LOCK=NONE is not allowed.
|
|
Upon marko's advice, I added some data to the test case, this one and one from MDEV-16060. Now I get "Invalid (old?) table or database name" on 10.0 and 10.1 as well. Release builds are much more willing to produce it than debug, but it happens on both after enough attempts.
I paste both test cases, because the probability of getting the error seems to vary depending on 10.0/10.1, innodb_plugin/xtradb, and debug/release – with some combinations one test case gives better results, and on other combinations the other one.
Please note that on 10.1 they need to be run with --mysqld=--sequence and on 10.0 with --mysqld=--sequence --mysqld=--plugin-load-add=ha_sequence (and with --repeat of course.
--source include/have_innodb.inc
|
|
CREATE TABLE t1 (`pk` INT PRIMARY KEY, f1 INT NOT NULL, INDEX ind_f1 (f1)) ENGINE=InnoDB;
|
CREATE TABLE t2 (`pk` INT PRIMARY KEY, f2 INT NOT NULL, INDEX ind_f2 (f2)) ENGINE=InnoDB;
|
|
--connect (con1,localhost,root,,test)
|
CREATE TABLE t3 (`pk` INT PRIMARY KEY, f3 INT NOT NULL, INDEX ind_f3 (f3)) ENGINE=InnoDB;
|
CREATE TABLE t4 (`pk` INT PRIMARY KEY, f4 INT NOT NULL, INDEX ind_f4 (f4)) ENGINE=InnoDB;
|
CREATE TABLE t5 (`pk` INT PRIMARY KEY, f5 INT NOT NULL, INDEX ind_f5 (f5), FOREIGN KEY (`pk`) REFERENCES t4 (`pk`) ON DELETE CASCADE ON UPDATE CASCADE) ENGINE=InnoDB;
|
|
INSERT INTO t4 SELECT seq, seq FROM seq_1_to_10000;
|
INSERT INTO t3 SELECT seq, seq FROM seq_1_to_10000;
|
INSERT INTO t5 SELECT seq, seq FROM seq_1_to_10000;
|
INSERT INTO t2 SELECT seq, seq FROM seq_1_to_10000;
|
INSERT INTO t1 SELECT seq, seq FROM seq_1_to_10000;
|
|
--send
|
ALTER TABLE t3 ADD CONSTRAINT fk3 FOREIGN KEY (`pk`) REFERENCES t5 (`pk`) ON DELETE CASCADE ON UPDATE CASCADE;
|
|
--connection default
|
UPDATE IGNORE t4 SET pk = 10001 WHERE `pk` = 1;
|
|
--connection con1
|
--error 0,ER_NO_REFERENCED_ROW_2,ER_ERROR_ON_RENAME
|
--reap
|
ALTER TABLE t1 ADD CONSTRAINT fk1 FOREIGN KEY (f1) REFERENCES t2 (`pk`) ON DELETE CASCADE ON UPDATE CASCADE;
|
|
# Cleanup
|
--disconnect con1
|
--connection default
|
DROP TABLE t3, t1, t5, t4, t2;
|
--source include/have_innodb.inc
|
|
CREATE TABLE t1 (a INT NOT NULL) ENGINE=InnoDB;
|
CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=InnoDB;
|
|
INSERT INTO t2 SELECT seq FROM seq_1_to_100000;
|
INSERT INTO t1 SELECT seq FROM seq_1_to_100000;
|
|
--connect (con1,localhost,root,,)
|
--send
|
ALTER TABLE t1 ADD CONSTRAINT FOREIGN KEY (a) REFERENCES t2(b) ON DELETE CASCADE ON UPDATE CASCADE;
|
|
--connection default
|
CREATE TABLE t3 LIKE t1;
|
UPDATE t2 SET b = b + 100000 LIMIT 2;
|
--connection con1
|
--error 0,ER_NO_REFERENCED_ROW_2,ER_ERROR_ON_RENAME
|
--reap
|
|
--disconnect con1
|
--connection default
|
SELECT * FROM t1 WHERE a NOT IN (SELECT b FROM t2);
|
DROP TABLE IF EXISTS t3;
|
DROP TABLE IF EXISTS t1;
|
DROP TABLE IF EXISTS t2;
|
|
10.0 bf4244d1a0d
|
line
|
180627 21:08:03 [ERROR] Invalid (old?) table or database name '#sql-118e_4'
|
^ Found warnings in /data/bld/10.0-rel/mysql-test/var/log/mysqld.1.err
|
|
threads