[MDEV-25942] Assertion `!table.n_waiting_or_granted_auto_inc_locks' failed in trx_t::drop_table Created: 2021-06-16  Updated: 2021-06-30  Resolved: 2021-06-30

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6
Fix Version/s: 10.6.3

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression


 Description    

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (k INT) ENGINE=InnoDB;
 
INSERT INTO t1 (k) VALUES (1);
 
START TRANSACTION;
 
INSERT INTO t1 (k) VALUES (2);
 
 
 
--connect (con1,localhost,root,,test)
 
SET innodb_lock_wait_timeout= 1;
 
--error ER_LOCK_WAIT_TIMEOUT
 
CREATE TABLE t2 (pk INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB AS SELECT k FROM t1;
 
 
 
# Cleanup
 
--disconnect con1
 
--connection default
 
DROP TABLE t1;

10.6 e5b9dc15

 
mariadbd: /data/src/10.6/storage/innobase/dict/drop.cc:154: dberr_t trx_t::drop_table(const dict_table_t&): Assertion `!table.n_waiting_or_granted_auto_inc_locks' failed.
 
210617  0:49:17 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fa452dd3f36 in __GI___assert_fail (assertion=0x5642bc01ebd0 "!table.n_waiting_or_granted_auto_inc_locks", file=0x5642bc01e8b8 "/data/src/10.6/storage/innobase/dict/drop.cc", line=154, function=0x5642bc01eb48 "dberr_t trx_t::drop_table(const dict_table_t&)") at assert.c:101
 
#8  0x00005642bb9b3e46 in trx_t::drop_table (this=0x7fa44d2c7290, table=...) at /data/src/10.6/storage/innobase/dict/drop.cc:154
 
#9  0x00005642bb65855d in ha_innobase::delete_table (this=0x7fa4140195f8, name=0x7fa447fb24f0 "./test/t2") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:13375
 
#10 0x00005642bb1c08b6 in hton_drop_table (hton=0x5642bdd3a3f8, path=0x7fa447fb24f0 "./test/t2") at /data/src/10.6/sql/handler.cc:576
 
#11 0x00005642bb1c6a15 in ha_delete_table (thd=0x7fa414000db8, hton=0x5642bdd3a3f8, path=0x7fa447fb24f0 "./test/t2", db=0x7fa4140142e0, alias=0x7fa4140142f0, generate_warning=false) at /data/src/10.6/sql/handler.cc:3071
 
#12 0x00005642baf2e69e in quick_rm_table (thd=0x7fa414000db8, base=0x5642bdd3a3f8, db=0x7fa4140142e0, table_name=0x7fa4140142f0, flags=0, table_path=0x0) at /data/src/10.6/sql/sql_table.cc:1921
 
#13 0x00005642bad8aec9 in drop_open_table (thd=0x7fa414000db8, table=0x7fa414026848, db_name=0x7fa4140142e0, table_name=0x7fa4140142f0) at /data/src/10.6/sql/sql_base.cc:1365
 
#14 0x00005642badf6b07 in select_create::abort_result_set (this=0x7fa414016458) at /data/src/10.6/sql/sql_insert.cc:5168
 
#15 0x00005642bae848df in handle_select (thd=0x7fa414000db8, lex=0x7fa414005068, result=0x7fa414016458, setup_tables_done_option=0) at /data/src/10.6/sql/sql_select.cc:562
 
#16 0x00005642baf4c992 in Sql_cmd_create_table_like::execute (this=0x7fa414014268, thd=0x7fa414000db8) at /data/src/10.6/sql/sql_table.cc:11729
 
#17 0x00005642bae4457e in mysql_execute_command (thd=0x7fa414000db8) at /data/src/10.6/sql/sql_parse.cc:5983
 
#18 0x00005642bae4a724 in mysql_parse (thd=0x7fa414000db8, rawbuf=0x7fa414014160 "CREATE TABLE t2 (pk INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB AS SELECT k FROM t1", length=85, parser_state=0x7fa447fb3480) at /data/src/10.6/sql/sql_parse.cc:8016
 
#19 0x00005642bae36bae in dispatch_command (command=COM_QUERY, thd=0x7fa414000db8, packet=0x7fa41400b879 "CREATE TABLE t2 (pk INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB AS SELECT k FROM t1", packet_length=85, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1897
 
#20 0x00005642bae35553 in do_command (thd=0x7fa414000db8, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1406
 
#21 0x00005642baff1d65 in do_handle_one_connection (connect=0x5642be291238, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
 
#22 0x00005642baff1ac1 in handle_one_connection (arg=0x5642be291238) at /data/src/10.6/sql/sql_connect.cc:1312
 
#23 0x00005642bb560fe9 in pfs_spawn_thread (arg=0x5642be2fdf68) at /data/src/10.6/storage/perfschema/pfs.cc:2201
 
#24 0x00007fa4532eb609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#25 0x00007fa452ebf293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

No obvious immediate problem on a non-debug build.
The failure started happening in 10.6 after this commit:

commit 1bd681c8b3c5213ce1f7976940a7dc38b48a0d39
 
Author: Marko Mäkelä <marko.makela@mariadb.com>
 
Date:   Wed Jun 9 17:02:55 2021 +0300
 
 
 
    MDEV-25506 (3 of 3): Do not delete .ibd files before commit
 
    
    This is a complete rewrite of DROP TABLE, also as part of other DDL,



 Comments   
Comment by Marko Mäkelä [ 2021-06-28 ]

Thank you. I fixed this by removing the assertion.

Remaining debug assertions will check that only this transaction is holding locks on the table, and that one of them is an exclusive lock.

Comment by Elena Stepanova [ 2021-06-29 ]

The same test case from the description still fails, now on a different assertion.

10.6 c2ebe8147d

 
mariadbd: /data/src/10.6-bug/storage/innobase/dict/drop.cc:165: dberr_t trx_t::drop_table(const dict_table_t&): Assertion `lock->type_mode == (LOCK_IX | 8U)' failed.
 
210630  2:35:27 [ERROR] mysqld got signal 6 ;
 
 
 
torage/innobase/dict/drop.cc", line=165, function=0x55699c692d20 "dberr_t trx_t::drop_table(const dict_table_t&)") at assert.c:101
 
#8  0x000055699c022f2f in trx_t::drop_table (this=0x7fa3dca09280, table=...) at /data/src/10.6-bug/storage/innobase/dict/drop.cc:165
 
#9  0x000055699bcc75c5 in ha_innobase::delete_table (this=0x7fa3a40195f8, name=0x7fa3d76fd4f0 "./test/t2") at /data/src/10.6-bug/storage/innobase/handler/ha_innodb.cc:13490
 
#10 0x000055699b82e010 in hton_drop_table (hton=0x55699e269c48, path=0x7fa3d76fd4f0 "./test/t2") at /data/src/10.6-bug/sql/handler.cc:576
 
#11 0x000055699b8343ae in ha_delete_table (thd=0x7fa3a4000db8, hton=0x55699e269c48, path=0x7fa3d76fd4f0 "./test/t2", db=0x7fa3a40142e0, alias=0x7fa3a40142f0, generate_warning=false) at /data/src/10.6-bug/sql/handler.cc:3086
 
#12 0x000055699b59bb80 in quick_rm_table (thd=0x7fa3a4000db8, base=0x55699e269c48, db=0x7fa3a40142e0, table_name=0x7fa3a40142f0, flags=0, table_path=0x0) at /data/src/10.6-bug/sql/sql_table.cc:1921
 
#13 0x000055699b3f7f2b in drop_open_table (thd=0x7fa3a4000db8, table=0x7fa3a4026848, db_name=0x7fa3a40142e0, table_name=0x7fa3a40142f0) at /data/src/10.6-bug/sql/sql_base.cc:1365
 
#14 0x000055699b463b79 in select_create::abort_result_set (this=0x7fa3a4016458) at /data/src/10.6-bug/sql/sql_insert.cc:5168
 
#15 0x000055699b4f1dff in handle_select (thd=0x7fa3a4000db8, lex=0x7fa3a4005068, result=0x7fa3a4016458, setup_tables_done_option=0) at /data/src/10.6-bug/sql/sql_select.cc:562
 
#16 0x000055699b5b9f1c in Sql_cmd_create_table_like::execute (this=0x7fa3a4014268, thd=0x7fa3a4000db8) at /data/src/10.6-bug/sql/sql_table.cc:11751
 
#17 0x000055699b4b1774 in mysql_execute_command (thd=0x7fa3a4000db8, is_called_from_prepared_stmt=false) at /data/src/10.6-bug/sql/sql_parse.cc:5995
 
#18 0x000055699b4b791f in mysql_parse (thd=0x7fa3a4000db8, rawbuf=0x7fa3a4014160 "CREATE TABLE t2 (pk INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB AS SELECT k FROM t1", length=85, parser_state=0x7fa3d76fe480) at /data/src/10.6-bug/sql/sql_parse.cc:8028
 
#19 0x000055699b4a3d59 in dispatch_command (command=COM_QUERY, thd=0x7fa3a4000db8, packet=0x7fa3a400b879 "CREATE TABLE t2 (pk INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB AS SELECT k FROM t1", packet_length=85, blocking=true) at /data/src/10.6-bug/sql/sql_parse.cc:1898
 
#20 0x000055699b4a26f5 in do_command (thd=0x7fa3a4000db8, blocking=true) at /data/src/10.6-bug/sql/sql_parse.cc:1406
 
#21 0x000055699b65f3cb in do_handle_one_connection (connect=0x55699e80c4f8, put_in_cache=true) at /data/src/10.6-bug/sql/sql_connect.cc:1410
 
#22 0x000055699b65f127 in handle_one_connection (arg=0x55699e80c4f8) at /data/src/10.6-bug/sql/sql_connect.cc:1312
 
#23 0x000055699bbcf313 in pfs_spawn_thread (arg=0x55699e80c5d8) at /data/src/10.6-bug/storage/perfschema/pfs.cc:2201
 
#24 0x00007fa3e2a2e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#25 0x00007fa3e2601293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

On the next fixing attempt, whether it's removing another assertion or anything else, please add the test case to the regression suite.

Comment by Marko Mäkelä [ 2021-06-30 ]

Sorry, it indeed looks like I must have forgotten to rerun the test case after removing the assertion. The remaining failing assertion must be relaxed as well, because the current transaction may hold an auto-increment lock on the table in addition to holding an exclusive lock.

Initially I did not want to add the test case to the regression suite, because it includes a lock wait timeout and thus increases the regression test run time by a whole second (since in MDEV-24671 we did not expose the subsecond precision of pthread_cond_timedwait() to the user). I have now added the test case to the regression test suite.

Comment by Elena Stepanova [ 2021-06-30 ]

For the regression suite you can use innodb_lock_wait_timeout= 0 instead.

Comment by Marko Mäkelä [ 2021-06-30 ]

You are right; I wrongly remembered that the value 0 would be infinite, while in fact it is an immediate timeout. Values between 100,000,000 and 1,073,741,824 would be an infinite timeout. On systems with 32-bit time_t, the 99,999,999-second timeout (3 years, 62 days and 9 hours) would become an immediate timeout if the wake-up time would be after some time in the year 2038.

Generated at Thu Feb 08 09:41:34 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.