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

Invalid (old?) table or database name or hang in ha_innobase::delete_table and log semaphore wait upon concurrent DDL with foreign keys

    XMLWordPrintable

    Details

      Description

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (a INT NOT NULL) ENGINE=InnoDB;
      CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=InnoDB;
       
      --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 = 1;
      --connection con1
      --reap
       
      --disconnect con1
      --connection default
      DROP TABLE IF EXISTS t3;
      DROP TABLE IF EXISTS t1;
      DROP TABLE IF EXISTS t2;
      

      The test case is non-deterministic, so it can end up differently.
      Sometimes it just passes.
      Sometimes it executes to the end, but fails with

      10.2 a31e99a89cc75

      2018-06-11 21:16:45 140673673762560 [ERROR] Invalid (old?) table or database name '#sql-8e9_a'
      ^ Found warnings in /data/bld/10.2/mysql-test/var/log/mysqld.1.err
      

      Sometimes it hangs upon DROP TABLE

      10.2 a31e99a89cc75

      Thread 3 (Thread 0x7f6e6c094700 (LWP 2482)):
      #0  0x00007f6e7af0b7dd in nanosleep () at ../sysdeps/unix/syscall-template.S:84
      #1  0x0000556ea3926439 in os_thread_sleep (tm=20000) at /data/src/10.2/storage/innobase/os/os0thread.cc:230
      #2  0x0000556ea39a8d90 in fil_wait_crypt_bg_threads (table=0x7f6e18020e58) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3175
      #3  0x0000556ea39a9e6e in row_drop_table_for_mysql (name=0x7f6e6c0907c0 "test/t1", trx=0x7f6e6f1967e8, drop_db=false, create_failed=0, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3549
      #4  0x0000556ea3876c81 in ha_innobase::delete_table (this=0x7f6e24012d60, name=0x7f6e6c092300 "./test/t1") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13270
      #5  0x0000556ea355ee90 in handler::ha_delete_table (this=0x7f6e24012d60, name=0x7f6e6c092300 "./test/t1") at /data/src/10.2/sql/handler.cc:4325
      #6  0x0000556ea35598c2 in ha_delete_table (thd=0x7f6e24000b00, table_type=0x556ea6ca6b10, path=0x7f6e6c092300 "./test/t1", db=0x7f6e24012b30 "test", alias=0x7f6e240124e8 "t1", generate_warning=true) at /data/src/10.2/sql/handler.cc:2352
      #7  0x0000556ea33a41f0 in mysql_rm_table_no_locks (thd=0x7f6e24000b00, tables=0x7f6e24012520, if_exists=true, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.2/sql/sql_table.cc:2468
      #8  0x0000556ea33a340d in mysql_rm_table (thd=0x7f6e24000b00, tables=0x7f6e24012520, if_exists=1 '\001', drop_temporary=0 '\000') at /data/src/10.2/sql/sql_table.cc:2088
      #9  0x0000556ea32e5e47 in mysql_execute_command (thd=0x7f6e24000b00) at /data/src/10.2/sql/sql_parse.cc:4756
      #10 0x0000556ea32efe49 in mysql_parse (thd=0x7f6e24000b00, rawbuf=0x7f6e24012448 "DROP TABLE IF EXISTS t1", length=23, parser_state=0x7f6e6c093200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7999
      #11 0x0000556ea32dd8f2 in dispatch_command (command=COM_QUERY, thd=0x7f6e24000b00, packet=0x7f6e240088a1 "DROP TABLE IF EXISTS t1", packet_length=23, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1821
      #12 0x0000556ea32dc255 in do_command (thd=0x7f6e24000b00) at /data/src/10.2/sql/sql_parse.cc:1375
      #13 0x0000556ea342ba66 in do_handle_one_connection (connect=0x556ea71cc470) at /data/src/10.2/sql/sql_connect.cc:1335
      #14 0x0000556ea342b7f3 in handle_one_connection (arg=0x556ea71cc470) at /data/src/10.2/sql/sql_connect.cc:1241
      #15 0x0000556ea384ccc0 in pfs_spawn_thread (arg=0x556ea71d69e0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      #16 0x00007f6e7af02494 in start_thread (arg=0x7f6e6c094700) at pthread_create.c:333
      #17 0x00007f6e792e893f in clone () from /lib/x86_64-linux-gnu/libc.so.6
       
      Thread 2 (Thread 0x7f6e6c04a700 (LWP 2485)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
      #1  0x0000556ea3cb72e1 in safe_cond_timedwait (cond=0x556ea4861f60 <COND_thread_cache>, mp=0x556ea4864800 <LOCK_thread_cache>, abstime=0x7f6e6c049da0, file=0x556ea3d46b40 "/data/src/10.2/include/mysql/psi/mysql_thread.h", line=1175) at /data/src/10.2/mysys/thr_mutex.c:545
      #2  0x0000556ea31fa60a in inline_mysql_cond_timedwait (that=0x556ea4861f60 <COND_thread_cache>, mutex=0x556ea4864800 <LOCK_thread_cache>, abstime=0x7f6e6c049da0, src_file=0x556ea3d488aa "/data/src/10.2/sql/mysqld.cc", src_line=2973) at /data/src/10.2/include/mysql/psi/mysql_thread.h:1175
      #3  0x0000556ea31ff72a in cache_thread (thd=0x7f6e18000b00) at /data/src/10.2/sql/mysqld.cc:2972
      #4  0x0000556ea31ff9ce in one_thread_per_connection_end (thd=0x7f6e18000b00, put_in_cache=true) at /data/src/10.2/sql/mysqld.cc:3061
      #5  0x0000556ea342bb4f in do_handle_one_connection (connect=0x556ea71b3fe0) at /data/src/10.2/sql/sql_connect.cc:1354
      #6  0x0000556ea342b7f3 in handle_one_connection (arg=0x556ea71b3fe0) at /data/src/10.2/sql/sql_connect.cc:1241
      #7  0x0000556ea384ccc0 in pfs_spawn_thread (arg=0x556ea71d6d90) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      #8  0x00007f6e7af02494 in start_thread (arg=0x7f6e6c04a700) at pthread_create.c:333
      #9  0x00007f6e792e893f in clone () from /lib/x86_64-linux-gnu/libc.so.6
       
      Thread 1 (Thread 0x7f6e7b31bb80 (LWP 2453)):
      #0  0x00007f6e792df4ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
      #1  0x0000556ea320648b in handle_connections_sockets () at /data/src/10.2/sql/mysqld.cc:6604
      #2  0x0000556ea320577a in mysqld_main (argc=144, argv=0x556ea6a69370) at /data/src/10.2/sql/mysqld.cc:6070
      #3  0x0000556ea31f9dc0 in main (argc=22, argv=0x7fff70057978) at /data/src/10.2/sql/main.cc:25
      

      (all threads are attached).
      When it hangs, it produces periodic error messages in the error log:

      2018-06-11 21:17:50 140112235677440 [Warning] InnoDB: Waited 30 seconds for ref-count on table: `test`.`t1` space: 7
      2018-06-11 21:18:20 140112235677440 [Warning] InnoDB: Waited 60 seconds for ref-count on table: `test`.`t1` space: 7
      

      and in due time starts to complain about long semaphore wait

      2018-06-11 21:32:16 139934062102272 [Warning] InnoDB: Waited 240 seconds for ref-count on table: `test`.`t1` space: 7
      2018-06-11 21:32:19 139933834528512 [Warning] InnoDB: A long semaphore wait:
      --Thread 139933817743104 has waited at srv0srv.cc line 2095 for 241.00 seconds the semaphore:
      X-lock on RW-latch at 0x55d7d08ea4b0 created in file dict0dict.cc line 1108
      a writer (thread id 139934062102272) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 853
      Last time write locked in file row0mysql.cc line 3356
      2018-06-11 21:32:19 139933834528512 [Note] InnoDB: A semaphore wait:
      --Thread 139933817743104 has waited at srv0srv.cc line 2095 for 241.00 seconds the semaphore:
      X-lock on RW-latch at 0x55d7d08ea4b0 created in file dict0dict.cc line 1108
      a writer (thread id 139934062102272) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 853
      Last time write locked in file row0mysql.cc line 3356
      

      Doesn't seem to be reproducible on 10.1

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              serg Sergei Golubchik
              Reporter:
              elenst Elena Stepanova
              Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: