[MDEV-33104] Assertion `table.get_ref_count() <= 1' failed in dberr_t trx_t::drop_table Created: 2023-12-21  Updated: 2024-01-19  Resolved: 2024-01-19

Status: Closed
Project: MariaDB Server
Component/s: Locking, Storage Engine - InnoDB
Affects Version/s: 10.6, 10.11, 11.0, 11.1, 11.2, 11.3
Fix Version/s: N/A

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Done Votes: 1
Labels: foreign-keys, regression, rr-profile-analyzed

Issue Links:
Relates
relates to MDEV-26990 DDL_LOG error in the log and errno 16... Stalled
relates to MDEV-32899 InnoDB is holding shared dict_sys.lat... Closed
relates to MDEV-21175 Remove dict_table_t::n_foreign_key_ch... Closed
relates to MDEV-26217 Failing assertion: list.count > 0 in ... Closed
relates to MDEV-26554 Table-rebuilding DDL on parent table ... Closed

 Description   

I've set versions tentatively to 10.6+, as that's where the failure has been recently observed in concurrent tests. Please adjust if needed.

10.11 2b8dc7668a21c88568f2848dffd5f9ce725eae9e

mysqld: /data/MDEV-33104/10.11/storage/innobase/dict/drop.cc:156: dberr_t trx_t::drop_table(const dict_table_t&): Assertion `table.get_ref_count() <= 1' failed.
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000320b2a5e1859 in __GI_abort () at abort.c:79
#2  0x0000320b2a5e1729 in __assert_fail_base (fmt=0x320b2a777588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55a9c67b314d "table.get_ref_count() <= 1", 
    file=0x55a9c67b2e68 "/data/MDEV-33104/10.11/storage/innobase/dict/drop.cc", line=156, function=<optimized out>) at assert.c:92
#3  0x0000320b2a5f2fd6 in __GI___assert_fail (assertion=0x55a9c67b314d "table.get_ref_count() <= 1", file=0x55a9c67b2e68 "/data/MDEV-33104/10.11/storage/innobase/dict/drop.cc", line=156, 
    function=0x55a9c67b3108 "dberr_t trx_t::drop_table(const dict_table_t&)") at assert.c:101
#4  0x000055a9c60ca387 in trx_t::drop_table (this=0x3a38709ec380, table=...) at /data/MDEV-33104/10.11/storage/innobase/dict/drop.cc:156
#5  0x000055a9c5dc255d in commit_try_rebuild (ha_alter_info=0x70776ede9ef0, ctx=0x1523bc0dd2b8, altered_table=0x70776ede9fb0, old_table=0x321c5801e228, statistics_exist=true, trx=0x3a38709ec380, 
    table_name=0x321c58028c0a "D") at /data/MDEV-33104/10.11/storage/innobase/handler/handler0alter.cc:10337
#6  0x000055a9c5db0e09 in ha_innobase::commit_inplace_alter_table (this=0x321c58108690, altered_table=0x70776ede9fb0, ha_alter_info=0x70776ede9ef0, commit=true)
    at /data/MDEV-33104/10.11/storage/innobase/handler/handler0alter.cc:11482
#7  0x000055a9c5a2f9b0 in handler::ha_commit_inplace_alter_table (this=0x321c58108690, altered_table=0x70776ede9fb0, ha_alter_info=0x70776ede9ef0, commit=true) at /data/MDEV-33104/10.11/sql/handler.cc:5292
#8  0x000055a9c57941a5 in mysql_inplace_alter_table (thd=0x1523bc002558, table_list=0x1523bc014c88, table=0x321c5801e228, altered_table=0x70776ede9fb0, ha_alter_info=0x70776ede9ef0, 
    target_mdl_request=0x70776edea7a0, ddl_log_state=0x70776ede9eb0, trigger_param=0x70776edea380, alter_ctx=0x70776edeb370, partial_alter=@0x70776ede9db6: false, start_alter_id=@0x70776ede9df0: 0, 
    if_exists=false) at /data/MDEV-33104/10.11/sql/sql_table.cc:7870
#9  0x000055a9c579dcb4 in mysql_alter_table (thd=0x1523bc002558, new_db=0x1523bc0070c0, new_name=0x1523bc007520, create_info=0x70776edec200, table_list=0x1523bc014c88, recreate_info=0x70776edec070, 
    alter_info=0x70776edec090, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/MDEV-33104/10.11/sql/sql_table.cc:11015
#10 0x000055a9c5848ece in Sql_cmd_alter_table::execute (this=0x1523bc0153a0, thd=0x1523bc002558) at /data/MDEV-33104/10.11/sql/sql_alter.cc:688
#11 0x000055a9c56874b7 in mysql_execute_command (thd=0x1523bc002558, is_called_from_prepared_stmt=false) at /data/MDEV-33104/10.11/sql/sql_parse.cc:6075
#12 0x000055a9c568cf44 in mysql_parse (thd=0x1523bc002558, rawbuf=0x1523bc014b40 "/* WRK-5 QNO 4822 */  ALTER TABLE `simple_db`.`D` FORCE", length=55, parser_state=0x70776eded340)
    at /data/MDEV-33104/10.11/sql/sql_parse.cc:8080
#13 0x000055a9c5679cd3 in dispatch_command (command=COM_QUERY, thd=0x1523bc002558, packet=0x1523bc00c7d9 "/* WRK-5 QNO 4822 */  ALTER TABLE `simple_db`.`D` FORCE ", packet_length=56, blocking=true)
    at /data/MDEV-33104/10.11/sql/sql_parse.cc:1894
#14 0x000055a9c56788d0 in do_command (thd=0x1523bc002558, blocking=true) at /data/MDEV-33104/10.11/sql/sql_parse.cc:1407
#15 0x000055a9c583e029 in do_handle_one_connection (connect=0x55a9c8eeedf8, put_in_cache=true) at /data/MDEV-33104/10.11/sql/sql_connect.cc:1415
#16 0x000055a9c583ddb5 in handle_one_connection (arg=0x55a9c8eeedf8) at /data/MDEV-33104/10.11/sql/sql_connect.cc:1317
#17 0x00007dee5aebe609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#18 0x0000320b2a6de133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

I have an impression that the failure started happening not very long ago (but probably before Q4 2023 release). However, it's not impossible that its appearance was triggered not by code changes but by some test changes.

Effect on non-debug builds:
So far I haven't observed any visible problem on a non-debug build (no hang etc).



 Comments   
Comment by Marko Mäkelä [ 2023-12-22 ]

There is one unexpected table reference, being held by the another DDL operation that is waiting for exclusive InnoDB table locks:

10.11 2b8dc7668a21c88568f2848dffd5f9ce725eae9e

Thread 19 (Thread 2805853.2805880):
#13 0x000055a9c61f4978 in safe_cond_timedwait (cond=0x3a38709ecf10, mp=0x55a9c78bc240 <lock_sys+192>, abstime=0x5aff30044fc0, file=0x55a9c66e0e50 "/data/MDEV-33104/10.11/storage/innobase/lock/lock0lock.cc", line=2033) at /data/MDEV-33104/10.11/mysys/thr_mutex.c:548
#14 0x000055a9c5e07d5e in lock_wait (thr=0x55a9c8f6ad00) at /data/MDEV-33104/10.11/storage/innobase/lock/lock0lock.cc:2033
#15 0x000055a9c5f22f39 in row_mysql_handle_errors (new_err=0x5aff30045204, trx=0x3a38709ece80, thr=0x55a9c8f6ad00, savept=0x0) at /data/MDEV-33104/10.11/storage/innobase/row/row0mysql.cc:688
#16 0x000055a9c5e0f670 in lock_table_for_trx (table=0x4a57c0f4620, trx=0x3a38709ece80, mode=LOCK_X, no_wait=false) at /data/MDEV-33104/10.11/storage/innobase/lock/lock0lock.cc:3971
#17 0x000055a9c5e0f7fc in lock_table_children (table=0x4a57c212a60, trx=0x3a38709ece80) at /data/MDEV-33104/10.11/storage/innobase/lock/lock0lock.cc:4001
#18 0x000055a9c5dafb10 in ha_innobase::commit_inplace_alter_table (this=0x5aff2c053670, altered_table=0x5aff30045fb0, ha_alter_info=0x5aff30045ef0, commit=true) at /data/MDEV-33104/10.11/storage/innobase/handler/handler0alter.cc:11227
#19 0x000055a9c5a2f9b0 in handler::ha_commit_inplace_alter_table (this=0x5aff2c053670, altered_table=0x5aff30045fb0, ha_alter_info=0x5aff30045ef0, commit=true) at /data/MDEV-33104/10.11/sql/handler.cc:5292
#20 0x000055a9c57941a5 in mysql_inplace_alter_table (thd=0x55a9c8f39108, table_list=0x55a9c8f49a50, table=0x1523c00293f8, altered_table=0x5aff30045fb0, ha_alter_info=0x5aff30045ef0, target_mdl_request=0x5aff300467a0, ddl_log_state=0x5aff30045eb0, trigger_param=0x5aff30046380, alter_ctx=0x5aff30047370, partial_alter=@0x5aff30045db6: false, start_alter_id=@0x5aff30045df0: 0, if_exists=false) at /data/MDEV-33104/10.11/sql/sql_table.cc:7870
#21 0x000055a9c579dcb4 in mysql_alter_table (thd=0x55a9c8f39108, new_db=0x55a9c8f3dc70, new_name=0x55a9c8f3e0d0, create_info=0x5aff30048200, table_list=0x55a9c8f49a50, recreate_info=0x5aff30048070, alter_info=0x5aff30048090, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/MDEV-33104/10.11/sql/sql_table.cc:11015
#22 0x000055a9c5848ece in Sql_cmd_alter_table::execute (this=0x55a9c8f4a298, thd=0x55a9c8f39108) at /data/MDEV-33104/10.11/sql/sql_alter.cc:688
#23 0x000055a9c56874b7 in mysql_execute_command (thd=0x55a9c8f39108, is_called_from_prepared_stmt=false) at /data/MDEV-33104/10.11/sql/sql_parse.cc:6075
#24 0x000055a9c568cf44 in mysql_parse (thd=0x55a9c8f39108, rawbuf=0x55a9c8f49860 "/* WRK-2 QNO 4286 */  ALTER TABLE `simple_db`.`DD` ADD KEY IF NOT EXISTS ord_index_274_2805522 ( `col_varchar_key` ), ALGORITHM = INPLACE", length=137, parser_state=0x5aff30049340) at /data/MDEV-33104/10.11/sql/sql_parse.cc:8080

The assertion fails in Thread 2, which is trying to drop the table simple_db.D after completing the rebuild of that table:

/* WRK-5 QNO 4822 */  ALTER TABLE `simple_db`.`D` FORCE;

The wait for InnoDB table locks was added in MDEV-26217 and MDEV-26554 as a work-around for insufficient metadata locks around DDL operations. I think that the metadata locking had better be fixed.

Comment by Elena Stepanova [ 2023-12-24 ]

The failure didn't start happening after the above-mentioned bugs were closed in 10.6.5/10.6.8. As the description says, it started happening recently. I have now ruled out possible test modifications as a cause and am quite certain that it was triggered by code changes, most likely by

commit 569da6a7bab034fc9768af88d8dbc2a8e2944764 (HEAD)
Author: Marko Mäkelä
Date:   Tue Nov 28 15:50:41 2023 +0200
 
    MDEV-32899 InnoDB is holding shared dict_sys.latch while waiting for FOREIGN KEY child table lock on DDL

I've raised it tentatively to a blocker (as a regression since the latest release) at least until further analysis is done. After that, if it turns out to be harmless, please feel free to demote.

Comment by Marko Mäkelä [ 2024-01-02 ]

Before the fix of MDEV-32899, dict_sys.latch ought to reduce the probability of this scenario.

To prevent this failure scenario, I think that the caller of handler::commit_inplace_alter_table(commit=true) must hold MDL_EXCLUSIVE on all tables that have FOREIGN KEY…REFERENCES pointing to the table that is being altered, as well as on all tables that are pointed to by the current or altered REFERENCES clauses of the being-altered table. In that way, the lock wait would happen on a metadata lock (MDL) object, outside any InnoDB object that may have to be freed during the course of the ALTER TABLE. InnoDB locks are always connected to a dict_table_t object, which is roughly equivalent to TABLE_SHARE. Many ALTER TABLE operations will involve creating a new dict_table_t object.

Comment by Marko Mäkelä [ 2024-01-12 ]

To prevent this race condition between two concurrently committing ALTER TABLE that are modifying a parent and a child table, I think that at the start of handler::commit_inplace_alter_table(commit=true) a meta-data lock must be held in MDL_EXCLUSIVE mode on the immediate parent and child tables. Adding this metadata lock acquisition to handler::commit_inplace_alter_table() itself would have the benefit that we’d only do it when the table needs to be rebuilt or reloaded later on in that function.

It is not clear to me how this MDL acquisition would be implemented and whether deadlocks would be detected by other means than lock_wait_timeout.

Comment by Aleksey Midenkov [ 2024-01-16 ]

There is only this interface:

/**
  Acquire exclusive locks. There must be no granted locks in the
  context.
 
  This is a replacement of lock_table_names(). It is used in
  RENAME, DROP and other DDL SQL statements.
 
  @param  mdl_requests  List of requests for locks to be acquired.
 
  @param lock_wait_timeout  Seconds to wait before timeout.
 
  @note The list of requests should not contain non-exclusive lock requests.
        There should not be any acquired locks in the context.
 
  @note Assumes that one already owns scoped intention exclusive lock.
 
  @retval FALSE  Success
  @retval TRUE   Failure
*/
 
bool MDL_context::acquire_locks(MDL_request_list *mdl_requests,
                                double lock_wait_timeout)

Comment by Marko Mäkelä [ 2024-01-16 ]

As far as I can tell, a MDL_context would be available to InnoDB by calling thd_mdl_context(thd), which returns a pointer to thd->mdl_context. However, before invoking handler::commit_inplace_alter_table(), mysql_inplace_alter_table() would already have called wait_while_table_is_used() to acquire MDL_EXCLUSIVE on the name of the table that is being altered. Therefore, the condition There must be no granted locks in the context cannot be met. In fact, even if that call was removed, a metadata lock in some shared mode would still be granted in the current thd->mdl_context.

Comment by Marko Mäkelä [ 2024-01-16 ]

serg claimed in a call that there is a deadlock detector within the MDL subsystem.

Since we are trying to prevent a conflict with another DDL operation (which would hold MDL_EXCLUSIVE on its being-ALTERed table), I think that the MDL_SHARED that InnoDB could acquire by invoking MDL_context::acquire_lock() should be sufficient. When it comes to MDL timeouts or deadlocks, we see that in fact, ha_innobase::commit_inplace_alter_table() is already invoking MDL_context::acquire_lock() via dict_acquire_mdl_shared<false>() on the InnoDB persistent statistics tables.

I will work on a fix based on this.

Comment by Marko Mäkelä [ 2024-01-19 ]

Based on some debugging with rr, I believe that we can get the complete list of parent and child table names in ha_innobase::commit_inplace_alter_table() by traversing ctx0->old_table->referenced_set, ctx0->old_table->foreign_set, as well as ctx0->add_fk under a shared dict_sys.latch. We should be able to create MDL_ticket for all names, release the shared dict_sys.latch, and invoke MDL_context::acquire_lock() on each MDL_ticket. (Until MDEV-12483 is done, no FOREIGN KEY relationship can be defined on partitioned tables.)

Comment by Marko Mäkelä [ 2024-01-19 ]

The only existing regression test where my added code would capture more than 1 table name that is connected by a FOREIGN KEY constraint is for the following statement before the first server restart in the test innodb.innodb-index:

alter table t2 add primary key (alpha), change a alpha int,
change b beta int, modify c int not null;

The ADD PRIMARY KEY implies a table rebuild, hence the table needs to be rebuilt. The captured names are t1, t3, and t4.

Come to think of it, there could be an easier fix of this: modify lock_table_children() so that it instead of simply acquiring a reference on each child table, it would invoke MDL_context::acquire_lock() first. To fix this particular bug scenario (as well as possibly in general), we do not have to acquire any locks on any parent tables, that is, the table traversal in lock_table_children() should be sufficient.

Comment by Marko Mäkelä [ 2024-01-19 ]

MDEV-32899 was reverted and reopened to significantly reduce the probability of this crash, or to possibly prevent it altogether. A future revised fix of MDEV-32899 will have to be tested more extensively.

Generated at Thu Feb 08 10:36:25 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.