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

Failing assertion: table->get_ref_count() == 0 or user_table->get_ref_count() == 1 when running ALTER TABLE

Details

    Description

      On a production server, we experience a crash during an alter table. I have attached the relevant entries from syslog (which is where MariaDB logs to), along with a similar SQL creation statement for the table that was altered. Unfortunately, the table in question was marked as crashed after the service restarted, and there was multiple entries per second being written to the error log about the table being crashed. Another member of the development team made the decision to drop the original table, and we don't have a backup of that table (it is a new table, being used as a summary table).

      The main known difference between the attached SQL for the table and the original is that the original had Foreign Keys to other tables. If you feel this might be relevant, I can attempt to find the foreign keys that were in place, along with the table definitions of those the target tables.

      MDEV-14021 has a similar crash (same assertion fail), so setting as relates to (I don't know enough about this bug to say if it is the same or not).

      Attachments

        1. MariaDb Crash.txt
          5 kB
        2. my.cnf
          6 kB
        3. syslog.portion
          15 kB
        4. table.sql
          3 kB

        Issue Links

          Activity

            rmhumphries Robert Humphries created issue -
            rmhumphries Robert Humphries made changes -
            Field Original Value New Value
            elenst Elena Stepanova made changes -
            Assignee Matthias Leich [ mleich ]
            elenst Elena Stepanova made changes -
            Fix Version/s 10.2 [ 14601 ]
            elenst Elena Stepanova made changes -
            Fix Version/s 10.2 [ 14601 ]

            From the error log:

            2018-04-04 13:09:45 0x7f24d8054700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.13/storage/innobase/row/row0merge.cc line 4476
            InnoDB: Failing assertion: table->get_ref_count() == 0
            InnoDB: We intentionally generate a memory trap.
            InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
            InnoDB: If you get repeated assertion failures or crashes, even
            InnoDB: immediately after the mysqld startup, there may be
            InnoDB: corruption in the InnoDB tablespace. Please refer to
            InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/
            InnoDB: about forcing recovery.
            180404 13:09:45 [ERROR] mysqld got signal 6 ;
            This could be because you hit a bug. It is also possible that this binary
            or one of the libraries it was linked against is corrupt, improperly built,
            or misconfigured. This error can also be caused by malfunctioning hardware.
            To report this bug, see https://mariadb.com/kb/en/reporting-bugs
            We will try our best to scrape up some info that will hopefully help
            diagnose the problem, but since we have already crashed,
            something is definitely wrong and this may fail.
            Server version: 10.2.13-MariaDB-10.2.13+maria~xenial
            key_buffer_size=268435456
            read_buffer_size=1048576
            max_used_connections=84
            max_threads=302
            thread_count=50
            It is possible that mysqld could use up to
            key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 887066 K  bytes of memory
            Hope that's ok; if not, decrease some variables in the equation.
            Thread pointer: 0x7f2269cf2c08
            Attempting backtrace. You can use the following information to find out
            where mysqld died. If you see no messages after this, something went
            terribly wrong...
            stack_bottom = 0x7f24d8053cc8 thread_stack 0x49000
            /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5587ece6612e]
            /usr/sbin/mysqld(handle_fatal_signal+0x345)[0x5587ec900b95]
            /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f250234e390]
            /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f250191d428]
            /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f250191f02a]
            /usr/sbin/mysqld(+0x40c252)[0x5587ec6b1252]
            /usr/sbin/mysqld(+0x9678fc)[0x5587ecc0c8fc]
            /usr/sbin/mysqld(+0x8c6f9f)[0x5587ecb6bf9f]
            /usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2c11)[0x5587ec7ede71]
            /usr/sbin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x5f4)[0x5587ec8392e4]
            /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x143f)[0x5587ec762e1f]
            /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x28a)[0x5587ec76a81a]
            /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1f09)[0x5587ec76d5b9]
            /usr/sbin/mysqld(_Z10do_commandP3THD+0x13c)[0x5587ec76de7c]
            /usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x24a)[0x5587ec83646a]
            /usr/sbin/mysqld(handle_one_connection+0x3d)[0x5587ec8365dd]
            /usr/sbin/mysqld(+0x7f4481)[0x5587eca99481]
            /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f25023446ba]
            /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f25019ef41d]
            Trying to get some variables.
            Some pointers may be invalid and cause the dump to abort.
            Query (0x7f226dd3a090): ALTER TABLE `pingtree`.`sumApplicationOutcomes`  ADD COLUMN `masterCustomerID` BIGINT(20) UNSIGNED NOT NULL AFTER `customerInsertDT`
            Connection ID (thread ID): 4430674
            Status: NOT_KILLED
            Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
            

            elenst Elena Stepanova added a comment - From the error log: 2018-04-04 13:09:45 0x7f24d8054700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.13/storage/innobase/row/row0merge.cc line 4476 InnoDB: Failing assertion: table->get_ref_count() == 0 InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ InnoDB: about forcing recovery. 180404 13:09:45 [ERROR] mysqld got signal 6 ; This could be because you hit a bug. It is also possible that this binary or one of the libraries it was linked against is corrupt, improperly built, or misconfigured. This error can also be caused by malfunctioning hardware. To report this bug, see https://mariadb.com/kb/en/reporting-bugs We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is definitely wrong and this may fail. Server version: 10.2.13-MariaDB-10.2.13+maria~xenial key_buffer_size=268435456 read_buffer_size=1048576 max_used_connections=84 max_threads=302 thread_count=50 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 887066 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x7f2269cf2c08 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x7f24d8053cc8 thread_stack 0x49000 /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5587ece6612e] /usr/sbin/mysqld(handle_fatal_signal+0x345)[0x5587ec900b95] /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f250234e390] /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f250191d428] /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f250191f02a] /usr/sbin/mysqld(+0x40c252)[0x5587ec6b1252] /usr/sbin/mysqld(+0x9678fc)[0x5587ecc0c8fc] /usr/sbin/mysqld(+0x8c6f9f)[0x5587ecb6bf9f] /usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2c11)[0x5587ec7ede71] /usr/sbin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x5f4)[0x5587ec8392e4] /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x143f)[0x5587ec762e1f] /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x28a)[0x5587ec76a81a] /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1f09)[0x5587ec76d5b9] /usr/sbin/mysqld(_Z10do_commandP3THD+0x13c)[0x5587ec76de7c] /usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x24a)[0x5587ec83646a] /usr/sbin/mysqld(handle_one_connection+0x3d)[0x5587ec8365dd] /usr/sbin/mysqld(+0x7f4481)[0x5587eca99481] /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f25023446ba] /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f25019ef41d] Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (0x7f226dd3a090): ALTER TABLE `pingtree`.`sumApplicationOutcomes` ADD COLUMN `masterCustomerID` BIGINT(20) UNSIGNED NOT NULL AFTER `customerInsertDT` Connection ID (thread ID): 4430674 Status: NOT_KILLED Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
            elenst Elena Stepanova made changes -
            Fix Version/s 10.2 [ 14601 ]
            elenst Elena Stepanova made changes -
            Fix Version/s 10.2 [ 14601 ]

            mleich,

            When we were discussing MDEV-17167 (similar assertion, different location), I think you mentioned that you were getting some of those in your tests. Could you please check if any of the failures you were getting could be related to this issue, and if so, see if it can be reproduced?

            elenst Elena Stepanova added a comment - mleich , When we were discussing MDEV-17167 (similar assertion, different location), I think you mentioned that you were getting some of those in your tests. Could you please check if any of the failures you were getting could be related to this issue, and if so, see if it can be reproduced?
            bartbogdan Bart made changes -
            Attachment MariaDb Crash.txt [ 46650 ]
            bartbogdan Bart added a comment -

            We have experienced a similar crash on a production server last week, after the crash the table mentioned in the log was corrupted and had to be dropped.
            I have attached the error log.
            MariaDb Crash.txt

            bartbogdan Bart added a comment - We have experienced a similar crash on a production server last week, after the crash the table mentioned in the log was corrupted and had to be dropped. I have attached the error log. MariaDb Crash.txt
            elenst Elena Stepanova added a comment - - edited

            bartbogdan, could you please paste or attach your config file(s)? (and/or rmhumphries, if you still have them).

            elenst Elena Stepanova added a comment - - edited bartbogdan , could you please paste or attach your config file(s)? (and/or rmhumphries , if you still have them).
            elenst Elena Stepanova made changes -
            Assignee Matthias Leich [ mleich ]
            elenst Elena Stepanova made changes -
            Labels crash crash need_feedback
            rmhumphries Robert Humphries made changes -
            Attachment my.cnf [ 46781 ]

            Hi @Elena Stepanova

            Please find attached. Note this is the current config file, but I am not aware of any changes since creating the ticket (but I can't guarantee it).

            Thanks,
            Robert my.cnf

            rmhumphries Robert Humphries added a comment - Hi @Elena Stepanova Please find attached. Note this is the current config file, but I am not aware of any changes since creating the ticket (but I can't guarantee it). Thanks, Robert my.cnf
            elenst Elena Stepanova made changes -
            Labels crash need_feedback crash
            elenst Elena Stepanova made changes -
            Assignee Elena Stepanova [ elenst ]
            elenst Elena Stepanova made changes -
            Status Open [ 1 ] Confirmed [ 10101 ]
            elenst Elena Stepanova added a comment - - edited

            Here is at least one (non-deterministic) test case which causes the same assertion failure on non-debug builds, and a similar one on debug builds. Run with --repeat=N --mem, it usually fails for me within 5 attempts, but it can vary on different machines and builds.

            --source include/have_innodb.inc
             
            CREATE TABLE t1 (
              pk INT,
              i INT,
              PRIMARY KEY (pk),
              KEY(i),
              FOREIGN KEY (pk) REFERENCES t1 (i)
            ) ENGINE=InnoDB;
             
            --connect (con1,localhost,root,,test)
            --send
              ALTER TABLE t1 ADD FOREIGN KEY (i) REFERENCES t1 (pk);
             
            --connection default
            INSERT INTO t1 SELECT * FROM t1;
            PREPARE stmt FROM 'INSERT INTO t1 SELECT * FROM t1';
            EXECUTE stmt;
            ALTER TABLE t1 FORCE;
             
            # Cleanup
            --connection con1
            --reap
            --disconnect con1
            --connection default
            DROP TABLE t1;
            

            10.2 non-debug dc2856ad6

            2018-12-21 23:50:49 0x7fc0902d9700  InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/row/row0merge.cc line 4465
            InnoDB: Failing assertion: table->get_ref_count() == 0
             
            #4  0x00007fc09660d3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
            #5  0x000055db865a32a3 in ut_dbg_assertion_failed (expr=expr@entry=0x55db86dfa3b0 "table->get_ref_count() == 0", file=file@entry=0x55db86df9950 "/data/src/10.2/storage/innobase/row/row0merge.cc", line=line@entry=4465) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60
            #6  0x000055db86ab5254 in row_merge_drop_table (trx=trx@entry=0x7fc090576198, table=<optimized out>) at /data/src/10.2/storage/innobase/row/row0merge.cc:4465
            #7  0x000055db86a1fcda in ha_innobase::commit_inplace_alter_table (this=0x7fc03c093880, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:9085
            #8  0x000055db866ddce6 in mysql_inplace_alter_table (target_mdl_request=0x7fc0902d4c20, alter_ctx=0x7fc0902d57e0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, ha_alter_info=0x7fc0902d4b90, altered_table=0x7fc03c029a88, table=0x7fc03c0a6e68, table_list=0x7fc03c00f168, thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_table.cc:7391
            #9  mysql_alter_table (thd=0x7fc03c0009a8, new_db=<optimized out>, new_name=<optimized out>, create_info=<optimized out>, table_list=0x7fc03c00f168, alter_info=<optimized out>, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9392
            #10 0x000055db86726a2d in Sql_cmd_alter_table::execute (this=0x2, thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_alter.cc:329
            #11 0x000055db8664e0bc in mysql_execute_command (thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_parse.cc:6227
            #12 0x000055db8665642a in mysql_parse (thd=0x7fc03c0009a8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:8014
            #13 0x000055db86659fa4 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fc03c0009a8, packet=packet@entry=0x7fc03c006ce9 "ALTER TABLE t1 FORCE", packet_length=packet_length@entry=20, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1825
            #14 0x000055db8665a9d9 in do_command (thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_parse.cc:1379
            #15 0x000055db86723d44 in do_handle_one_connection (connect=connect@entry=0x55db88db2d78) at /data/src/10.2/sql/sql_connect.cc:1335
            #16 0x000055db86723ee4 in handle_one_connection (arg=arg@entry=0x55db88db2d78) at /data/src/10.2/sql/sql_connect.cc:1241
            #17 0x000055db869e8994 in pfs_spawn_thread (arg=0x55db88d74df8) at /data/src/10.2/storage/perfschema/pfs.cc:1862
            #18 0x00007fc0980c0494 in start_thread (arg=0x7fc0902d9700) at pthread_create.c:333
            #19 0x00007fc0966c193f in clone () from /lib/x86_64-linux-gnu/libc.so.6
            

            10.2 debug dc2856ad6

            mysqld: /data/src/10.2/storage/innobase/handler/handler0alter.cc:7881: bool commit_try_rebuild(Alter_inplace_info*, ha_innobase_inplace_ctx*, TABLE*
            , const TABLE*, trx_t*, const char*): Assertion `user_table->get_ref_count() == 1' failed.
            181221 23:51:34 [ERROR] mysqld got signal 6 ;
             
            #7  0x00007f44935faee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
            #8  0x0000558e03fdb82a in commit_try_rebuild (ha_alter_info=0x7f448c264610, ctx=0x7f443c013ad8, altered_table=0x7f443c051c50, old_table=0x7f443c08a7f0, trx=0x7f448d56e3a8, table_name=0x7f443c08727d "t1") at /data/src/10.2/storage/innobase/handler/handler0alter.cc:7881
            #9  0x0000558e03fd7e95 in ha_innobase::commit_inplace_alter_table (this=0x7f443c1333d8, altered_table=0x7f443c051c50, ha_alter_info=0x7f448c264610, commit=true) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:8660
            #10 0x0000558e03c8c337 in handler::ha_commit_inplace_alter_table (this=0x7f443c1333d8, altered_table=0x7f443c051c50, ha_alter_info=0x7f448c264610, commit=true) at /data/src/10.2/sql/handler.cc:4231
            #11 0x0000558e03ad9ffa in mysql_inplace_alter_table (thd=0x7f443c000b00, table_list=0x7f443c012520, table=0x7f443c08a7f0, altered_table=0x7f443c051c50, ha_alter_info=0x7f448c264610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f448c264680, alter_ctx=0x7f448c265240) at /data/src/10.2/sql/sql_table.cc:7391
            #12 0x0000558e03adf53b in mysql_alter_table (thd=0x7f443c000b00, new_db=0x7f443c012b30 "test", new_name=0x0, create_info=0x7f448c265e50, table_list=0x7f443c012520, alter_info=0x7f448c265da0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9392
            #13 0x0000558e03b5a89f in Sql_cmd_alter_table::execute (this=0x7f443c012b38, thd=0x7f443c000b00) at /data/src/10.2/sql/sql_alter.cc:329
            #14 0x0000558e03a11985 in mysql_execute_command (thd=0x7f443c000b00) at /data/src/10.2/sql/sql_parse.cc:6227
            #15 0x0000558e03a167e7 in mysql_parse (thd=0x7f443c000b00, rawbuf=0x7f443c012448 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7f448c267200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8014
            #16 0x0000558e03a0411f in dispatch_command (command=COM_QUERY, thd=0x7f443c000b00, packet=0x7f443c096191 "ALTER TABLE t1 FORCE", packet_length=20, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1825
            #17 0x0000558e03a02a82 in do_command (thd=0x7f443c000b00) at /data/src/10.2/sql/sql_parse.cc:1379
            #18 0x0000558e03b55535 in do_handle_one_connection (connect=0x558e06be3df0) at /data/src/10.2/sql/sql_connect.cc:1335
            #19 0x0000558e03b552c2 in handle_one_connection (arg=0x558e06be3df0) at /data/src/10.2/sql/sql_connect.cc:1241
            #20 0x0000558e03f7b1fc in pfs_spawn_thread (arg=0x558e06b2a1f0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
            #21 0x00007f44950b6494 in start_thread (arg=0x7f448c268700) at pthread_create.c:333
            #22 0x00007f44936b793f in clone () from /lib/x86_64-linux-gnu/libc.so.6
            

            Reproducible on 10.2, 10.3, 10.4.

            On 10.0 and 10.1 ALTER TABLE t1 FORCE fails immediately with 1205: Lock wait timeout exceeded; try restarting transaction, which of course is strange, because the default lock wait timeout is quite long and can't be exceeded so quickly.

            If we allow the statement to fail (add --error 0,ER_LOCK_WAIT_TIMEOUT before the statement), on 10.1 the test non-deterministically hangs upon DROP TABLE for 300 seconds, then gives up. I'm not sure where 300 seconds comes from.
            The processlist says

            +----+------+-----------------+------+---------+------+------------------+------------------+----------+
            | Id | User | Host            | db   | Command | Time | State            | Info             | Progress |
            +----+------+-----------------+------+---------+------+------------------+------------------+----------+
            |  8 | root | localhost       | test | Query   |   84 | Unlocking tables | DROP TABLE t1    |    0.000 |
            | 10 | root | localhost:58919 | NULL | Query   |    0 | init             | show processlist |    0.000 |
            +----+------+-----------------+------+---------+------+------------------+------------------+----------+
            

            Metadata lock info says

            MariaDB [(none)]> select * from information_schema.metadata_lock_info;
            +-----------+-------------------------+---------------+----------------------+--------------+------------+
            | THREAD_ID | LOCK_MODE               | LOCK_DURATION | LOCK_TYPE            | TABLE_SCHEMA | TABLE_NAME |
            +-----------+-------------------------+---------------+----------------------+--------------+------------+
            |         8 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock     |              |            |
            |         8 | MDL_EXCLUSIVE           | NULL          | Table metadata lock  | test         | t1         |
            |         8 | MDL_INTENTION_EXCLUSIVE | NULL          | Schema metadata lock | test         |            |
            +-----------+-------------------------+---------------+----------------------+--------------+------------+
            3 rows in set (0.00 sec)
            

            And the stack trace from the hanging process is

            10.1 9f4a4cb40

            Thread 2 (Thread 0x7f84224c1b00 (LWP 31871)):
            #0  0x00007f842071d233 in select () from /lib/x86_64-linux-gnu/libc.so.6
            #1  0x00007f8419b6ef30 in os_thread_sleep (tm=20000) at /data/src/10.1/storage/innobase/os/os0thread.cc:283
            #2  0x00007f8419beb4c8 in fil_wait_crypt_bg_threads (table=0x7f840a8d90f8) at /data/src/10.1/storage/innobase/row/row0mysql.cc:3313
            #3  0x00007f8419bed4c4 in row_drop_table_for_mysql (name=0x7f84224bdc20 "test/t1", trx=0x7f840a46ae78, drop_db=false, create_failed=0, nonatomic=true) at /data/src/10.1/storage/innobase/row/row0mysql.cc:4174
            #4  0x00007f8419ae59b2 in ha_innodb::delete_table (this=0x7f840a70d970, name=0x7f84224bf770 "./test/t1") at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:12592
            #5  0x0000562958aad4bc in handler::ha_delete_table (this=0x7f840a70d970, name=0x7f84224bf770 "./test/t1") at /data/src/10.1/sql/handler.cc:4317
            #6  0x0000562958aa862f in ha_delete_table (thd=0x7f8416fc7070, table_type=0x7f841fc37470, path=0x7f84224bf770 "./test/t1", db=0x7f840a70d740 "test", alias=0x7f840a70d118 "t1", generate_warning=true) at /data/src/10.1/sql/handler.cc:2385
            #7  0x000056295891b9d3 in mysql_rm_table_no_locks (thd=0x7f8416fc7070, tables=0x7f840a70d150, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.1/sql/sql_table.cc:2470
            #8  0x000056295891abfd in mysql_rm_table (thd=0x7f8416fc7070, tables=0x7f840a70d150, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.1/sql/sql_table.cc:2085
            #9  0x0000562958867bb3 in mysql_execute_command (thd=0x7f8416fc7070) at /data/src/10.1/sql/sql_parse.cc:4257
            #10 0x000056295887168b in mysql_parse (thd=0x7f8416fc7070, rawbuf=0x7f840a70d088 "DROP TABLE t1", length=13, parser_state=0x7f84224c05e0) at /data/src/10.1/sql/sql_parse.cc:7467
            #11 0x000056295885fedc in dispatch_command (command=COM_QUERY, thd=0x7f8416fc7070, packet=0x7f8416fd9071 "DROP TABLE t1", packet_length=13) at /data/src/10.1/sql/sql_parse.cc:1495
            #12 0x000056295885ec61 in do_command (thd=0x7f8416fc7070) at /data/src/10.1/sql/sql_parse.cc:1124
            #13 0x0000562958999988 in do_handle_one_connection (thd_arg=0x7f8416fc7070) at /data/src/10.1/sql/sql_connect.cc:1330
            #14 0x00005629589996ec in handle_one_connection (arg=0x7f8416fc7070) at /data/src/10.1/sql/sql_connect.cc:1242
            #15 0x0000562958d57982 in pfs_spawn_thread (arg=0x7f841b3f3f70) at /data/src/10.1/storage/perfschema/pfs.cc:1861
            #16 0x00007f8422150494 in start_thread (arg=0x7f84224c1b00) at pthread_create.c:333
            #17 0x00007f842072493f in clone () from /lib/x86_64-linux-gnu/libc.so.6
            

            On 10.0 the test (also non-deterministically) fails with

            bug.ref3 'xtradb'                        [ fail ]  Found warnings/errors in server log file!
                    Test ended at 2018-12-21 23:59:49
            line
            2018-12-21 23:59:49 7fcefed18700  InnoDB: Warning: MySQL is trying to drop table `test`.`t1`
            ^ Found warnings in /data/bld/10.0/mysql-test/var/log/mysqld.1.err
            

            elenst Elena Stepanova added a comment - - edited Here is at least one (non-deterministic) test case which causes the same assertion failure on non-debug builds, and a similar one on debug builds. Run with --repeat=N --mem , it usually fails for me within 5 attempts, but it can vary on different machines and builds. --source include/have_innodb.inc   CREATE TABLE t1 ( pk INT , i INT , PRIMARY KEY (pk), KEY (i), FOREIGN KEY (pk) REFERENCES t1 (i) ) ENGINE=InnoDB;   --connect (con1,localhost,root,,test) --send ALTER TABLE t1 ADD FOREIGN KEY (i) REFERENCES t1 (pk);   --connection default INSERT INTO t1 SELECT * FROM t1; PREPARE stmt FROM 'INSERT INTO t1 SELECT * FROM t1' ; EXECUTE stmt; ALTER TABLE t1 FORCE ;   # Cleanup --connection con1 --reap --disconnect con1 --connection default DROP TABLE t1; 10.2 non-debug dc2856ad6 2018-12-21 23:50:49 0x7fc0902d9700 InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/row/row0merge.cc line 4465 InnoDB: Failing assertion: table->get_ref_count() == 0   #4 0x00007fc09660d3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6 #5 0x000055db865a32a3 in ut_dbg_assertion_failed (expr=expr@entry=0x55db86dfa3b0 "table->get_ref_count() == 0", file=file@entry=0x55db86df9950 "/data/src/10.2/storage/innobase/row/row0merge.cc", line=line@entry=4465) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60 #6 0x000055db86ab5254 in row_merge_drop_table (trx=trx@entry=0x7fc090576198, table=<optimized out>) at /data/src/10.2/storage/innobase/row/row0merge.cc:4465 #7 0x000055db86a1fcda in ha_innobase::commit_inplace_alter_table (this=0x7fc03c093880, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:9085 #8 0x000055db866ddce6 in mysql_inplace_alter_table (target_mdl_request=0x7fc0902d4c20, alter_ctx=0x7fc0902d57e0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, ha_alter_info=0x7fc0902d4b90, altered_table=0x7fc03c029a88, table=0x7fc03c0a6e68, table_list=0x7fc03c00f168, thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_table.cc:7391 #9 mysql_alter_table (thd=0x7fc03c0009a8, new_db=<optimized out>, new_name=<optimized out>, create_info=<optimized out>, table_list=0x7fc03c00f168, alter_info=<optimized out>, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9392 #10 0x000055db86726a2d in Sql_cmd_alter_table::execute (this=0x2, thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_alter.cc:329 #11 0x000055db8664e0bc in mysql_execute_command (thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_parse.cc:6227 #12 0x000055db8665642a in mysql_parse (thd=0x7fc03c0009a8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:8014 #13 0x000055db86659fa4 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fc03c0009a8, packet=packet@entry=0x7fc03c006ce9 "ALTER TABLE t1 FORCE", packet_length=packet_length@entry=20, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1825 #14 0x000055db8665a9d9 in do_command (thd=0x7fc03c0009a8) at /data/src/10.2/sql/sql_parse.cc:1379 #15 0x000055db86723d44 in do_handle_one_connection (connect=connect@entry=0x55db88db2d78) at /data/src/10.2/sql/sql_connect.cc:1335 #16 0x000055db86723ee4 in handle_one_connection (arg=arg@entry=0x55db88db2d78) at /data/src/10.2/sql/sql_connect.cc:1241 #17 0x000055db869e8994 in pfs_spawn_thread (arg=0x55db88d74df8) at /data/src/10.2/storage/perfschema/pfs.cc:1862 #18 0x00007fc0980c0494 in start_thread (arg=0x7fc0902d9700) at pthread_create.c:333 #19 0x00007fc0966c193f in clone () from /lib/x86_64-linux-gnu/libc.so.6 10.2 debug dc2856ad6 mysqld: /data/src/10.2/storage/innobase/handler/handler0alter.cc:7881: bool commit_try_rebuild(Alter_inplace_info*, ha_innobase_inplace_ctx*, TABLE* , const TABLE*, trx_t*, const char*): Assertion `user_table->get_ref_count() == 1' failed. 181221 23:51:34 [ERROR] mysqld got signal 6 ;   #7 0x00007f44935faee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000558e03fdb82a in commit_try_rebuild (ha_alter_info=0x7f448c264610, ctx=0x7f443c013ad8, altered_table=0x7f443c051c50, old_table=0x7f443c08a7f0, trx=0x7f448d56e3a8, table_name=0x7f443c08727d "t1") at /data/src/10.2/storage/innobase/handler/handler0alter.cc:7881 #9 0x0000558e03fd7e95 in ha_innobase::commit_inplace_alter_table (this=0x7f443c1333d8, altered_table=0x7f443c051c50, ha_alter_info=0x7f448c264610, commit=true) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:8660 #10 0x0000558e03c8c337 in handler::ha_commit_inplace_alter_table (this=0x7f443c1333d8, altered_table=0x7f443c051c50, ha_alter_info=0x7f448c264610, commit=true) at /data/src/10.2/sql/handler.cc:4231 #11 0x0000558e03ad9ffa in mysql_inplace_alter_table (thd=0x7f443c000b00, table_list=0x7f443c012520, table=0x7f443c08a7f0, altered_table=0x7f443c051c50, ha_alter_info=0x7f448c264610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f448c264680, alter_ctx=0x7f448c265240) at /data/src/10.2/sql/sql_table.cc:7391 #12 0x0000558e03adf53b in mysql_alter_table (thd=0x7f443c000b00, new_db=0x7f443c012b30 "test", new_name=0x0, create_info=0x7f448c265e50, table_list=0x7f443c012520, alter_info=0x7f448c265da0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9392 #13 0x0000558e03b5a89f in Sql_cmd_alter_table::execute (this=0x7f443c012b38, thd=0x7f443c000b00) at /data/src/10.2/sql/sql_alter.cc:329 #14 0x0000558e03a11985 in mysql_execute_command (thd=0x7f443c000b00) at /data/src/10.2/sql/sql_parse.cc:6227 #15 0x0000558e03a167e7 in mysql_parse (thd=0x7f443c000b00, rawbuf=0x7f443c012448 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7f448c267200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8014 #16 0x0000558e03a0411f in dispatch_command (command=COM_QUERY, thd=0x7f443c000b00, packet=0x7f443c096191 "ALTER TABLE t1 FORCE", packet_length=20, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1825 #17 0x0000558e03a02a82 in do_command (thd=0x7f443c000b00) at /data/src/10.2/sql/sql_parse.cc:1379 #18 0x0000558e03b55535 in do_handle_one_connection (connect=0x558e06be3df0) at /data/src/10.2/sql/sql_connect.cc:1335 #19 0x0000558e03b552c2 in handle_one_connection (arg=0x558e06be3df0) at /data/src/10.2/sql/sql_connect.cc:1241 #20 0x0000558e03f7b1fc in pfs_spawn_thread (arg=0x558e06b2a1f0) at /data/src/10.2/storage/perfschema/pfs.cc:1862 #21 0x00007f44950b6494 in start_thread (arg=0x7f448c268700) at pthread_create.c:333 #22 0x00007f44936b793f in clone () from /lib/x86_64-linux-gnu/libc.so.6 Reproducible on 10.2, 10.3, 10.4. On 10.0 and 10.1 ALTER TABLE t1 FORCE fails immediately with 1205: Lock wait timeout exceeded; try restarting transaction , which of course is strange, because the default lock wait timeout is quite long and can't be exceeded so quickly. If we allow the statement to fail (add --error 0,ER_LOCK_WAIT_TIMEOUT before the statement), on 10.1 the test non-deterministically hangs upon DROP TABLE for 300 seconds, then gives up. I'm not sure where 300 seconds comes from. The processlist says +----+------+-----------------+------+---------+------+------------------+------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | +----+------+-----------------+------+---------+------+------------------+------------------+----------+ | 8 | root | localhost | test | Query | 84 | Unlocking tables | DROP TABLE t1 | 0.000 | | 10 | root | localhost:58919 | NULL | Query | 0 | init | show processlist | 0.000 | +----+------+-----------------+------+---------+------+------------------+------------------+----------+ Metadata lock info says MariaDB [(none)]> select * from information_schema.metadata_lock_info; +-----------+-------------------------+---------------+----------------------+--------------+------------+ | THREAD_ID | LOCK_MODE | LOCK_DURATION | LOCK_TYPE | TABLE_SCHEMA | TABLE_NAME | +-----------+-------------------------+---------------+----------------------+--------------+------------+ | 8 | MDL_INTENTION_EXCLUSIVE | NULL | Global read lock | | | | 8 | MDL_EXCLUSIVE | NULL | Table metadata lock | test | t1 | | 8 | MDL_INTENTION_EXCLUSIVE | NULL | Schema metadata lock | test | | +-----------+-------------------------+---------------+----------------------+--------------+------------+ 3 rows in set (0.00 sec) And the stack trace from the hanging process is 10.1 9f4a4cb40 Thread 2 (Thread 0x7f84224c1b00 (LWP 31871)): #0 0x00007f842071d233 in select () from /lib/x86_64-linux-gnu/libc.so.6 #1 0x00007f8419b6ef30 in os_thread_sleep (tm=20000) at /data/src/10.1/storage/innobase/os/os0thread.cc:283 #2 0x00007f8419beb4c8 in fil_wait_crypt_bg_threads (table=0x7f840a8d90f8) at /data/src/10.1/storage/innobase/row/row0mysql.cc:3313 #3 0x00007f8419bed4c4 in row_drop_table_for_mysql (name=0x7f84224bdc20 "test/t1", trx=0x7f840a46ae78, drop_db=false, create_failed=0, nonatomic=true) at /data/src/10.1/storage/innobase/row/row0mysql.cc:4174 #4 0x00007f8419ae59b2 in ha_innodb::delete_table (this=0x7f840a70d970, name=0x7f84224bf770 "./test/t1") at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:12592 #5 0x0000562958aad4bc in handler::ha_delete_table (this=0x7f840a70d970, name=0x7f84224bf770 "./test/t1") at /data/src/10.1/sql/handler.cc:4317 #6 0x0000562958aa862f in ha_delete_table (thd=0x7f8416fc7070, table_type=0x7f841fc37470, path=0x7f84224bf770 "./test/t1", db=0x7f840a70d740 "test", alias=0x7f840a70d118 "t1", generate_warning=true) at /data/src/10.1/sql/handler.cc:2385 #7 0x000056295891b9d3 in mysql_rm_table_no_locks (thd=0x7f8416fc7070, tables=0x7f840a70d150, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.1/sql/sql_table.cc:2470 #8 0x000056295891abfd in mysql_rm_table (thd=0x7f8416fc7070, tables=0x7f840a70d150, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.1/sql/sql_table.cc:2085 #9 0x0000562958867bb3 in mysql_execute_command (thd=0x7f8416fc7070) at /data/src/10.1/sql/sql_parse.cc:4257 #10 0x000056295887168b in mysql_parse (thd=0x7f8416fc7070, rawbuf=0x7f840a70d088 "DROP TABLE t1", length=13, parser_state=0x7f84224c05e0) at /data/src/10.1/sql/sql_parse.cc:7467 #11 0x000056295885fedc in dispatch_command (command=COM_QUERY, thd=0x7f8416fc7070, packet=0x7f8416fd9071 "DROP TABLE t1", packet_length=13) at /data/src/10.1/sql/sql_parse.cc:1495 #12 0x000056295885ec61 in do_command (thd=0x7f8416fc7070) at /data/src/10.1/sql/sql_parse.cc:1124 #13 0x0000562958999988 in do_handle_one_connection (thd_arg=0x7f8416fc7070) at /data/src/10.1/sql/sql_connect.cc:1330 #14 0x00005629589996ec in handle_one_connection (arg=0x7f8416fc7070) at /data/src/10.1/sql/sql_connect.cc:1242 #15 0x0000562958d57982 in pfs_spawn_thread (arg=0x7f841b3f3f70) at /data/src/10.1/storage/perfschema/pfs.cc:1861 #16 0x00007f8422150494 in start_thread (arg=0x7f84224c1b00) at pthread_create.c:333 #17 0x00007f842072493f in clone () from /lib/x86_64-linux-gnu/libc.so.6 On 10.0 the test (also non-deterministically) fails with bug.ref3 'xtradb' [ fail ] Found warnings/errors in server log file! Test ended at 2018-12-21 23:59:49 line 2018-12-21 23:59:49 7fcefed18700 InnoDB: Warning: MySQL is trying to drop table `test`.`t1` ^ Found warnings in /data/bld/10.0/mysql-test/var/log/mysqld.1.err
            elenst Elena Stepanova made changes -
            Summary Failing assertion: table->get_ref_count() == 0 when running ALTER TABLE ADD COLUMN Failing assertion: table->get_ref_count() == 0 or when running ALTER TABLE
            elenst Elena Stepanova made changes -
            Summary Failing assertion: table->get_ref_count() == 0 or when running ALTER TABLE Failing assertion: table->get_ref_count() == 0 or user_table->get_ref_count() == 1 when running ALTER TABLE

            Assigning to marko for the initial look. Possibly it belongs to svoj instead.
            Also, maybe we will need to split the two issues – assertion failures for 10.2+ and the hang for 10.0/10.1. I think we have had several users' reports about server hanging in 'Unlocking tables', they might be related.

            elenst Elena Stepanova added a comment - Assigning to marko for the initial look. Possibly it belongs to svoj instead. Also, maybe we will need to split the two issues – assertion failures for 10.2+ and the hang for 10.0/10.1. I think we have had several users' reports about server hanging in 'Unlocking tables', they might be related.
            elenst Elena Stepanova made changes -
            elenst Elena Stepanova made changes -
            Component/s Locking [ 10900 ]
            Fix Version/s 10.0 [ 16000 ]
            Fix Version/s 10.1 [ 16100 ]
            Fix Version/s 10.2 [ 14601 ]
            Fix Version/s 10.3 [ 22126 ]
            Fix Version/s 10.4 [ 22408 ]
            Affects Version/s 10.0 [ 16000 ]
            Affects Version/s 10.1 [ 16100 ]
            Affects Version/s 10.2 [ 14601 ]
            Affects Version/s 10.3 [ 22126 ]
            Affects Version/s 10.4 [ 22408 ]
            elenst Elena Stepanova made changes -
            Assignee Elena Stepanova [ elenst ] Marko Mäkelä [ marko ]
            elenst Elena Stepanova made changes -
            elenst Elena Stepanova made changes -
            Labels crash affects-tests crash
            marko Marko Mäkelä added a comment - - edited

            I ran elenst’s test with the following instrumentation on top of 10.2:

            diff --git a/storage/innobase/include/dict0dict.ic b/storage/innobase/include/dict0dict.ic
            index a10bf769773..7b83647469a 100644
            --- a/storage/innobase/include/dict0dict.ic
            +++ b/storage/innobase/include/dict0dict.ic
            @@ -25,6 +25,7 @@ Created 1/8/1996 Heikki Tuuri
             ***********************************************************************/
             
             #include "fsp0sysspace.h"
            +#include "my_stacktrace.h"
             
             /*********************************************************************//**
             Gets the minimum number of bytes per character.
            @@ -1498,6 +1499,9 @@ dict_table_t::acquire()
             {
             	ut_ad(mutex_own(&dict_sys->mutex));
             	my_atomic_add32_explicit(&n_ref_count, 1, MY_MEMORY_ORDER_RELAXED);
            +	if (id < 18) return;
            +	ib::info() << "acquired " << n_ref_count << "," << id << "," << name;
            +	my_print_stacktrace(NULL, 0);
             }
             
             /** Release the table handle.
            @@ -1509,6 +1513,9 @@ dict_table_t::release()
             	int32 n = my_atomic_add32_explicit(
             			&n_ref_count, -1, MY_MEMORY_ORDER_RELAXED);
             	ut_ad(n > 0);
            +	if (id < 18) return n == 1;
            +	ib::info() << "released " << n << "," << id << "," << name;
            +	my_print_stacktrace(NULL, 0);
             	return n == 1;
             }
             
            

            This will significantly reduce the probability of crashing for me, but it does still fail.
            Here is some edited output for the table ID 20, which was user_table->id in the core dump:

            2019-03-06 13:29:38 140283319162624 [Note] InnoDB: acquired 1,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(create_table_info_t::create_table_update_dict())[0x558098f5a73d]
            :0(ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, bool, trx_t*))[0x558098f6f489]
            sql/handler.cc:4442(handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*))[0x558098d9abc8]
            /dev/shm/10.2/sql/mysqld(ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*)+0x27f)[0x558098d9ba0f]
            sql/sql_table.cc:9505(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c5f3f0]
            …
            2019-03-06 13:29:38 140283319469824 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273]
            :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240]
            /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953]
            /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11]
            sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945]
            /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x413)[0x558098b6d7d3]
            sql/sql_prepare.cc:1807(select_like_stmt_test_with_open(Prepared_statement*, TABLE_LIST*, int (*)(THD*), unsigned long))[0x558098be2d81]
            sql/sql_prepare.cc:2240(mysql_test_insert_select(Prepared_statement*, TABLE_LIST*))[0x558098bdaad7]
            sql/sql_prepare.cc:2844(mysql_sql_stmt_prepare(THD*))[0x558098bdc833]
            sql/sql_parse.cc:3543(mysql_execute_command(THD*))[0x558098bc213c]
            sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433]
            sql/sql_parse.cc:1831(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x558098bbb230]
            /dev/shm/10.2/sql/mysqld(do_command(THD*)+0x4da)[0x558098bbce9a]
            sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x558098cb5aa0]
            …
            2019-03-06 13:29:39 140283319162624 [Note] InnoDB: released 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::release())[0x558098f712fe]
            dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674]
            :0(create_table_info_t::create_table_update_dict())[0x558098f5ab83]
            :0(ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, bool, trx_t*))[0x558098f6f489]
            sql/handler.cc:4442(handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*))[0x558098d9abc8]
            /dev/shm/10.2/sql/mysqld(ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*)+0x27f)[0x558098d9ba0f]
            sql/sql_table.cc:9505(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c5f3f0]
            …
            2019-03-06 13:29:39 140283319162624 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273]
            :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240]
            /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953]
            /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11]
            sql/temporary_tables.cc:1091(THD::open_temporary_table(TMP_TABLE_SHARE*, char const*, bool))[0x558098d2f364]
            /dev/shm/10.2/sql/mysqld(THD::create_and_open_tmp_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*, bool)+0x76)[0x558098d2ef36]
            sql/sql_table.cc:9514(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c5f430]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            …
            2019-03-06 13:29:39 140283319162624 [Note] InnoDB: released 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::release())[0x558098f712fe]
            dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674]
            row/row0mysql.cc:1038(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x55809906a55c]
            handler/ha_innodb.cc:6709(ha_innobase::close())[0x558098f4f791]
            /dev/shm/10.2/sql/mysqld(handler::ha_close()+0x91)[0x558098d95e41]
            /dev/shm/10.2/sql/mysqld(closefrm(TABLE*)+0x5e)[0x558098c8425e]
            sql/temporary_tables.cc:1213(THD::close_temporary_table(TABLE*))[0x558098d31af7]
            sql/temporary_tables.cc:1457(THD::free_temporary_table(TABLE*))[0x558098d306f7]
            /dev/shm/10.2/sql/mysqld(THD::drop_temporary_table(TABLE*, bool*, bool)+0x160)[0x558098d31200]
            sql/sql_table.cc:9663(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c61e26]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            … (snip quite a few operations for table ID 19)
            2019-03-06 13:29:41 140283319162624 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f6ff2c]
            :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860]
            /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db]
            /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            …
            2019-03-06 13:29:41 140283319162624 [Note] InnoDB: released 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::release())[0x558098f712fe]
            dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674]
            handler/ha_innodb.cc:13441(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f70006]
            :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860]
            /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db]
            /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            …
            2019-03-06 13:29:42 140283319162624 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            row/row0mysql.cc:4177(row_rename_table_for_mysql(char const*, char const*, trx_t*, bool, bool))[0x558099072b5c]
            :0(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f70044]
            :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860]
            /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db]
            /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            …
            2019-03-06 13:29:42 140283319162624 [Note] InnoDB: released 2,20,`test`.`t1`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::release())[0x558098f712fe]
            dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674]
            :0(row_rename_table_for_mysql(char const*, char const*, trx_t*, bool, bool))[0x55809907391f]
            :0(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f70044]
            :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860]
            /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db]
            /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            … (snip a couple of operations on ID 19, which had been renamed to sql2 name)
            2019-03-06 13:29:43 140283319469824 [Note] InnoDB: acquired 2,20,`test`.`t1`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273]
            :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240]
            /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953]
            /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11]
            sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945]
            /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0xb47)[0x558098b6df07]
            sql/sql_base.cc:4767(open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*))[0x558098b6f83b]
            sql/sql_parse.cc:4556(mysql_execute_command(THD*))[0x558098bc172b]
            sql/sql_prepare.cc:4805(Prepared_statement::execute(String*, bool))[0x558098bdfed0]
            sql/sql_prepare.cc:4234(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x558098bddcab]
            sql/sql_class.h:1342(mysql_sql_stmt_execute(THD*))[0x558098bdda67]
            sql/sql_parse.cc:3548(mysql_execute_command(THD*))[0x558098bc20ee]
            sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433]
            …
            2019-03-06 13:29:43 140283319469824 [Note] InnoDB: acquired 3,20,`test`.`t1`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273]
            :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240]
            /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953]
            /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11]
            sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945]
            /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0xb47)[0x558098b6df07]
            sql/sql_prepare.cc:1807(select_like_stmt_test_with_open(Prepared_statement*, TABLE_LIST*, int (*)(THD*), unsigned long))[0x558098be2d81]
            sql/sql_prepare.cc:2240(mysql_test_insert_select(Prepared_statement*, TABLE_LIST*))[0x558098bdaad7]
            /dev/shm/10.2/sql/mysqld(Prepared_statement::reprepare()+0xf5)[0x558098be0205]
            sql/sql_prepare.cc:4272(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x558098bddee4]
            sql/sql_class.h:1342(mysql_sql_stmt_execute(THD*))[0x558098bdda67]
            sql/sql_parse.cc:3548(mysql_execute_command(THD*))[0x558098bc20ee]
            sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433]
            …
            2019-03-06 13:29:43 140283319469824 [Note] InnoDB: acquired 4,20,`test`.`t1`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273]
            :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240]
            /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953]
            /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11]
            sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945]
            /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x413)[0x558098b6d7d3]
            sql/sql_prepare.cc:1807(select_like_stmt_test_with_open(Prepared_statement*, TABLE_LIST*, int (*)(THD*), unsigned long))[0x558098be2d81]
            sql/sql_prepare.cc:2240(mysql_test_insert_select(Prepared_statement*, TABLE_LIST*))[0x558098bdaad7]
            /dev/shm/10.2/sql/mysqld(Prepared_statement::reprepare()+0xf5)[0x558098be0205]
            sql/sql_prepare.cc:4272(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x558098bddee4]
            sql/sql_class.h:1342(mysql_sql_stmt_execute(THD*))[0x558098bdda67]
            sql/sql_parse.cc:3548(mysql_execute_command(THD*))[0x558098bc20ee]
            sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433]
            …
            2019-03-06 13:29:43 140283319469824 [Note] InnoDB: released 4,20,`test`.`t1`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::release())[0x558098f712fe]
            dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674]
            row/row0mysql.cc:1038(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x55809906a55c]
            handler/ha_innodb.cc:6709(ha_innobase::close())[0x558098f4f791]
            /dev/shm/10.2/sql/mysqld(handler::ha_close()+0x91)[0x558098d95e41]
            /dev/shm/10.2/sql/mysqld(closefrm(TABLE*)+0x5e)[0x558098c8425e]
            sql/table_cache.cc:223(intern_close_table(TABLE*))[0x558098d2dcdb]
            sql/sql_table.cc:7279(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x558098c61a45]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433]
            …
            2019-03-06 13:29:44 140283319469824 [Note] InnoDB: released 3,20,`test`.`t1`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::release())[0x558098f712fe]
            dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674]
            row/row0mysql.cc:1038(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x55809906a55c]
            handler/ha_innodb.cc:6709(ha_innobase::close())[0x558098f4f791]
            /dev/shm/10.2/sql/mysqld(handler::ha_close()+0x91)[0x558098d95e41]
            /dev/shm/10.2/sql/mysqld(closefrm(TABLE*)+0x5e)[0x558098c8425e]
            sql/table_cache.cc:223(intern_close_table(TABLE*))[0x558098d2dcdb]
            sql/sql_table.cc:7279(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x558098c61a45]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433]
            …
            2019-03-06 13:29:44 140283319469824 [Note] InnoDB: acquired 1,21,`test`.`#sql-2d09_9`
            stack_bottom = 0x0 thread_stack 0x0
            mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9]
            :0(dict_table_t::acquire())[0x5580991e9828]
            dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28]
            handler0alter.cc:0(prepare_inplace_alter_table_dict(Alter_inplace_info*, TABLE const*, TABLE const*, char const*, unsigned long, unsigned long, unsigned long, bool, bool))[0x558098f7c937]
            handler/handler0alter.cc:6292(ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x558098f77643]
            sql/sql_table.cc:7329(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x558098c61c09]
            /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760]
            /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e]
            … (snip only a little bit of stack trace)
            mysqld: /mariadb/10.2/storage/innobase/handler/handler0alter.cc:7906: bool commit_try_rebuild(Alter_inplace_info *, ha_innobase_inplace_ctx *, TABLE *, const TABLE *, trx_t *, const char *): Assertion `user_table->get_ref_count() == 1' failed.
            

            svoj, I think that the problem is the second acquisition. Either the PREPARE stmt or EXECUTE stmt is accessing the wrong table (with #sql name). I suppose that the EXECUTE stmt should be blocked while the first ALTER TABLE (which uses ALGORITHM=COPY) is executing. The wrong reference-count is merely caught during the second ALTER TABLE. This lingering reference should also cause a hang during DROP TABLE or similar.

            marko Marko Mäkelä added a comment - - edited I ran elenst ’s test with the following instrumentation on top of 10.2: diff --git a/storage/innobase/include/dict0dict.ic b/storage/innobase/include/dict0dict.ic index a10bf769773..7b83647469a 100644 --- a/storage/innobase/include/dict0dict.ic +++ b/storage/innobase/include/dict0dict.ic @@ -25,6 +25,7 @@ Created 1/8/1996 Heikki Tuuri ***********************************************************************/ #include "fsp0sysspace.h" +#include "my_stacktrace.h" /*********************************************************************//** Gets the minimum number of bytes per character. @@ -1498,6 +1499,9 @@ dict_table_t::acquire() { ut_ad(mutex_own(&dict_sys->mutex)); my_atomic_add32_explicit(&n_ref_count, 1, MY_MEMORY_ORDER_RELAXED); + if (id < 18) return; + ib::info() << "acquired " << n_ref_count << "," << id << "," << name; + my_print_stacktrace(NULL, 0); } /** Release the table handle. @@ -1509,6 +1513,9 @@ dict_table_t::release() int32 n = my_atomic_add32_explicit( &n_ref_count, -1, MY_MEMORY_ORDER_RELAXED); ut_ad(n > 0); + if (id < 18) return n == 1; + ib::info() << "released " << n << "," << id << "," << name; + my_print_stacktrace(NULL, 0); return n == 1; } This will significantly reduce the probability of crashing for me, but it does still fail. Here is some edited output for the table ID 20, which was user_table->id in the core dump: 2019-03-06 13:29:38 140283319162624 [Note] InnoDB: acquired 1,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(create_table_info_t::create_table_update_dict())[0x558098f5a73d] :0(ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, bool, trx_t*))[0x558098f6f489] sql/handler.cc:4442(handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*))[0x558098d9abc8] /dev/shm/10.2/sql/mysqld(ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*)+0x27f)[0x558098d9ba0f] sql/sql_table.cc:9505(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c5f3f0] … 2019-03-06 13:29:38 140283319469824 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273] :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240] /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953] /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11] sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945] /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x413)[0x558098b6d7d3] sql/sql_prepare.cc:1807(select_like_stmt_test_with_open(Prepared_statement*, TABLE_LIST*, int (*)(THD*), unsigned long))[0x558098be2d81] sql/sql_prepare.cc:2240(mysql_test_insert_select(Prepared_statement*, TABLE_LIST*))[0x558098bdaad7] sql/sql_prepare.cc:2844(mysql_sql_stmt_prepare(THD*))[0x558098bdc833] sql/sql_parse.cc:3543(mysql_execute_command(THD*))[0x558098bc213c] sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433] sql/sql_parse.cc:1831(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x558098bbb230] /dev/shm/10.2/sql/mysqld(do_command(THD*)+0x4da)[0x558098bbce9a] sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x558098cb5aa0] … 2019-03-06 13:29:39 140283319162624 [Note] InnoDB: released 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::release())[0x558098f712fe] dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674] :0(create_table_info_t::create_table_update_dict())[0x558098f5ab83] :0(ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, bool, trx_t*))[0x558098f6f489] sql/handler.cc:4442(handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*))[0x558098d9abc8] /dev/shm/10.2/sql/mysqld(ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*)+0x27f)[0x558098d9ba0f] sql/sql_table.cc:9505(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c5f3f0] … 2019-03-06 13:29:39 140283319162624 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273] :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240] /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953] /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11] sql/temporary_tables.cc:1091(THD::open_temporary_table(TMP_TABLE_SHARE*, char const*, bool))[0x558098d2f364] /dev/shm/10.2/sql/mysqld(THD::create_and_open_tmp_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*, bool)+0x76)[0x558098d2ef36] sql/sql_table.cc:9514(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c5f430] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … 2019-03-06 13:29:39 140283319162624 [Note] InnoDB: released 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::release())[0x558098f712fe] dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674] row/row0mysql.cc:1038(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x55809906a55c] handler/ha_innodb.cc:6709(ha_innobase::close())[0x558098f4f791] /dev/shm/10.2/sql/mysqld(handler::ha_close()+0x91)[0x558098d95e41] /dev/shm/10.2/sql/mysqld(closefrm(TABLE*)+0x5e)[0x558098c8425e] sql/temporary_tables.cc:1213(THD::close_temporary_table(TABLE*))[0x558098d31af7] sql/temporary_tables.cc:1457(THD::free_temporary_table(TABLE*))[0x558098d306f7] /dev/shm/10.2/sql/mysqld(THD::drop_temporary_table(TABLE*, bool*, bool)+0x160)[0x558098d31200] sql/sql_table.cc:9663(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x558098c61e26] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … (snip quite a few operations for table ID 19) 2019-03-06 13:29:41 140283319162624 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f6ff2c] :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860] /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db] /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … 2019-03-06 13:29:41 140283319162624 [Note] InnoDB: released 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::release())[0x558098f712fe] dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674] handler/ha_innodb.cc:13441(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f70006] :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860] /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db] /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … 2019-03-06 13:29:42 140283319162624 [Note] InnoDB: acquired 2,20,`test`.`#sql-2d09_a` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] row/row0mysql.cc:4177(row_rename_table_for_mysql(char const*, char const*, trx_t*, bool, bool))[0x558099072b5c] :0(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f70044] :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860] /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db] /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … 2019-03-06 13:29:42 140283319162624 [Note] InnoDB: released 2,20,`test`.`t1` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::release())[0x558098f712fe] dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674] :0(row_rename_table_for_mysql(char const*, char const*, trx_t*, bool, bool))[0x55809907391f] :0(innobase_rename_table(trx_t*, char const*, char const*, bool, bool))[0x558098f70044] :0(ha_innobase::rename_table(char const*, char const*))[0x558098f5b860] /dev/shm/10.2/sql/mysqld(mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int)+0x2bb)[0x558098c595db] /dev/shm/10.2/sql/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x5fd2)[0x558098c62842] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … (snip a couple of operations on ID 19, which had been renamed to sql2 name) 2019-03-06 13:29:43 140283319469824 [Note] InnoDB: acquired 2,20,`test`.`t1` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273] :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240] /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953] /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11] sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945] /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0xb47)[0x558098b6df07] sql/sql_base.cc:4767(open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*))[0x558098b6f83b] sql/sql_parse.cc:4556(mysql_execute_command(THD*))[0x558098bc172b] sql/sql_prepare.cc:4805(Prepared_statement::execute(String*, bool))[0x558098bdfed0] sql/sql_prepare.cc:4234(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x558098bddcab] sql/sql_class.h:1342(mysql_sql_stmt_execute(THD*))[0x558098bdda67] sql/sql_parse.cc:3548(mysql_execute_command(THD*))[0x558098bc20ee] sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433] … 2019-03-06 13:29:43 140283319469824 [Note] InnoDB: acquired 3,20,`test`.`t1` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273] :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240] /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953] /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11] sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945] /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0xb47)[0x558098b6df07] sql/sql_prepare.cc:1807(select_like_stmt_test_with_open(Prepared_statement*, TABLE_LIST*, int (*)(THD*), unsigned long))[0x558098be2d81] sql/sql_prepare.cc:2240(mysql_test_insert_select(Prepared_statement*, TABLE_LIST*))[0x558098bdaad7] /dev/shm/10.2/sql/mysqld(Prepared_statement::reprepare()+0xf5)[0x558098be0205] sql/sql_prepare.cc:4272(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x558098bddee4] sql/sql_class.h:1342(mysql_sql_stmt_execute(THD*))[0x558098bdda67] sql/sql_parse.cc:3548(mysql_execute_command(THD*))[0x558098bc20ee] sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433] … 2019-03-06 13:29:43 140283319469824 [Note] InnoDB: acquired 4,20,`test`.`t1` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] :0(ha_innobase::open_dict_table(char const*, char const*, bool, dict_err_ignore_t))[0x558098f4f273] :0(ha_innobase::open(char const*, int, unsigned int))[0x558098f4e240] /dev/shm/10.2/sql/mysqld(handler::ha_open(TABLE*, char const*, int, unsigned int)+0xe3)[0x558098d95953] /dev/shm/10.2/sql/mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool)+0xaf1)[0x558098c83d11] sql/sql_base.cc:1920(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x558098b6b945] /dev/shm/10.2/sql/mysqld(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x413)[0x558098b6d7d3] sql/sql_prepare.cc:1807(select_like_stmt_test_with_open(Prepared_statement*, TABLE_LIST*, int (*)(THD*), unsigned long))[0x558098be2d81] sql/sql_prepare.cc:2240(mysql_test_insert_select(Prepared_statement*, TABLE_LIST*))[0x558098bdaad7] /dev/shm/10.2/sql/mysqld(Prepared_statement::reprepare()+0xf5)[0x558098be0205] sql/sql_prepare.cc:4272(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x558098bddee4] sql/sql_class.h:1342(mysql_sql_stmt_execute(THD*))[0x558098bdda67] sql/sql_parse.cc:3548(mysql_execute_command(THD*))[0x558098bc20ee] sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433] … 2019-03-06 13:29:43 140283319469824 [Note] InnoDB: released 4,20,`test`.`t1` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::release())[0x558098f712fe] dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674] row/row0mysql.cc:1038(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x55809906a55c] handler/ha_innodb.cc:6709(ha_innobase::close())[0x558098f4f791] /dev/shm/10.2/sql/mysqld(handler::ha_close()+0x91)[0x558098d95e41] /dev/shm/10.2/sql/mysqld(closefrm(TABLE*)+0x5e)[0x558098c8425e] sql/table_cache.cc:223(intern_close_table(TABLE*))[0x558098d2dcdb] sql/sql_table.cc:7279(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x558098c61a45] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433] … 2019-03-06 13:29:44 140283319469824 [Note] InnoDB: released 3,20,`test`.`t1` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::release())[0x558098f712fe] dict/dict0dict.cc:503(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x5580991cf674] row/row0mysql.cc:1038(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x55809906a55c] handler/ha_innodb.cc:6709(ha_innobase::close())[0x558098f4f791] /dev/shm/10.2/sql/mysqld(handler::ha_close()+0x91)[0x558098d95e41] /dev/shm/10.2/sql/mysqld(closefrm(TABLE*)+0x5e)[0x558098c8425e] sql/table_cache.cc:223(intern_close_table(TABLE*))[0x558098d2dcdb] sql/sql_table.cc:7279(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x558098c61a45] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] sql/sql_class.h:2279(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558098bbe433] … 2019-03-06 13:29:44 140283319469824 [Note] InnoDB: acquired 1,21,`test`.`#sql-2d09_9` stack_bottom = 0x0 thread_stack 0x0 mysys/stacktrace.c:267(my_print_stacktrace)[0x5580993e8ca9] :0(dict_table_t::acquire())[0x5580991e9828] dict/dict0dict.cc:1212(dict_table_open_on_name(char const*, unsigned long, unsigned long, dict_err_ignore_t))[0x5580991d1c28] handler0alter.cc:0(prepare_inplace_alter_table_dict(Alter_inplace_info*, TABLE const*, TABLE const*, char const*, unsigned long, unsigned long, unsigned long, bool, bool))[0x558098f7c937] handler/handler0alter.cc:6292(ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x558098f77643] sql/sql_table.cc:7329(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*))[0x558098c61c09] /dev/shm/10.2/sql/mysqld(Sql_cmd_alter_table::execute(THD*)+0x4b0)[0x558098cb9760] /dev/shm/10.2/sql/mysqld(mysql_execute_command(THD*)+0x122e)[0x558098bc0f3e] … (snip only a little bit of stack trace) mysqld: /mariadb/10.2/storage/innobase/handler/handler0alter.cc:7906: bool commit_try_rebuild(Alter_inplace_info *, ha_innobase_inplace_ctx *, TABLE *, const TABLE *, trx_t *, const char *): Assertion `user_table->get_ref_count() == 1' failed. svoj , I think that the problem is the second acquisition. Either the PREPARE stmt or EXECUTE stmt is accessing the wrong table (with #sql name). I suppose that the EXECUTE stmt should be blocked while the first ALTER TABLE (which uses ALGORITHM=COPY ) is executing. The wrong reference-count is merely caught during the second ALTER TABLE . This lingering reference should also cause a hang during DROP TABLE or similar.
            marko Marko Mäkelä made changes -
            Assignee Marko Mäkelä [ marko ] Sergey Vojtovich [ svoj ]
            svoj Sergey Vojtovich made changes -

            Should've been fixed by MDEV-16060. Feel free to reopen if the problem persists.
            Verified test case provided by Elena to fail reliably without MDEV-16060 and not failing with it.

            svoj Sergey Vojtovich added a comment - Should've been fixed by MDEV-16060 . Feel free to reopen if the problem persists. Verified test case provided by Elena to fail reliably without MDEV-16060 and not failing with it.
            svoj Sergey Vojtovich made changes -
            Fix Version/s N/A [ 14700 ]
            Fix Version/s 10.2 [ 14601 ]
            Fix Version/s 10.0 [ 16000 ]
            Fix Version/s 10.1 [ 16100 ]
            Fix Version/s 10.3 [ 22126 ]
            Fix Version/s 10.4 [ 22408 ]
            Resolution Duplicate [ 3 ]
            Status Confirmed [ 10101 ] Closed [ 6 ]
            alice Alice Sherepa made changes -
            serg Sergei Golubchik made changes -
            Workflow MariaDB v3 [ 86381 ] MariaDB v4 [ 154092 ]

            People

              svoj Sergey Vojtovich
              rmhumphries Robert Humphries
              Votes:
              0 Vote for this issue
              Watchers:
              6 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.