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

    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: