[MDEV-17749] Kill during LOCK TABLE ; ALTER TABLE causes assert Created: 2018-11-16  Updated: 2021-06-04  Resolved: 2021-05-26

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Locking
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.6.2, 10.3.30, 10.4.20, 10.5.11

Type: Bug Priority: Critical
Reporter: Alice Sherepa Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: affects-tests

Issue Links:
Problem/Incident
is caused by MDEV-5587 Server crashes in Locked_tables_list:... Closed

 Description   

--source include/have_innodb.inc
 
CREATE TABLE t1 (a INT) ENGINE=InnoDB;
 
--connect (con1,localhost,root,,test)
LOCK TABLE t1 WRITE;
--let $conid= `SELECT CONNECTION_ID()`
--send
  ALTER TABLE t1 ADD COLUMN b INT;
 
--connection default
eval KILL $conid;
 
# Cleanup
DROP TABLE t1;

10.4 2d4b6571

mysqld: /data/src/10.4/sql/sql_base.cc:2455: void Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction.stmt.is_empty()' failed.
200114 13:50:15 [ERROR] mysqld got signal 6 ;
 
#7  0x00007ff8cad17f12 in __GI___assert_fail (assertion=0x55779cd65850 "thd->transaction.stmt.is_empty()", file=0x55779cd64fd0 "/data/src/10.4/sql/sql_base.cc", line=2455, function=0x55779cd67280 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "void Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x000055779bfdb370 in Locked_tables_list::unlock_locked_tables (this=0x7ff870004860, thd=0x7ff870000af0) at /data/src/10.4/sql/sql_base.cc:2455
#9  0x000055779bfdb7b3 in Locked_tables_list::unlink_all_closed_tables (this=0x7ff870004860, thd=0x7ff870000af0, lock=0x0, reopen_count=0) at /data/src/10.4/sql/sql_base.cc:2634
#10 0x000055779bfdba52 in Locked_tables_list::reopen_tables (this=0x7ff870004860, thd=0x7ff870000af0, need_reopen=false) at /data/src/10.4/sql/sql_base.cc:2688
#11 0x000055779c172e9e in mysql_alter_table (thd=0x7ff870000af0, new_db=0x7ff8700052b0, new_name=0x7ff8700056b8, create_info=0x7ff8c409bcf0, table_list=0x7ff870011ec0, alter_info=0x7ff8c409bc30, order_num=0, order=0x0, ignore=false) at /data/src/10.4/sql/sql_table.cc:10397
#12 0x000055779c20a341 in Sql_cmd_alter_table::execute (this=0x7ff8700126a8, thd=0x7ff870000af0) at /data/src/10.4/sql/sql_alter.cc:508
#13 0x000055779c088d95 in mysql_execute_command (thd=0x7ff870000af0) at /data/src/10.4/sql/sql_parse.cc:6102
#14 0x000055779c08e457 in mysql_parse (thd=0x7ff870000af0, rawbuf=0x7ff870011dd8 "ALTER TABLE t1 ADD COLUMN b INT", length=31, parser_state=0x7ff8c409d160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
#15 0x000055779c0795fc in dispatch_command (command=COM_QUERY, thd=0x7ff870000af0, packet=0x7ff8700083a1 "ALTER TABLE t1 ADD COLUMN b INT", packet_length=31, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
#16 0x000055779c077c89 in do_command (thd=0x7ff870000af0) at /data/src/10.4/sql/sql_parse.cc:1360
#17 0x000055779c200c51 in do_handle_one_connection (connect=0x5577a04668e0) at /data/src/10.4/sql/sql_connect.cc:1412
#18 0x000055779c2009a0 in handle_one_connection (arg=0x5577a04668e0) at /data/src/10.4/sql/sql_connect.cc:1316
#19 0x000055779cc06b0d in pfs_spawn_thread (arg=0x5577a03d3360) at /data/src/10.4/storage/perfschema/pfs.cc:1862
#20 0x00007ff8ccca04a4 in start_thread (arg=0x7ff8c409e700) at pthread_create.c:456
#21 0x00007ff8cadd4d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducible with 10.1-10.5.
The test case fails for me every time, but it still involves a race condition, so try to run with --repeat=N if it doesn't fail right away.
No obvious problem on a non-debug build.



 Comments   
Comment by Roel Van de Paar [ 2020-04-22 ]

One more testcase which requires USE_FRM on REPAIR TABLE

USE test;
CREATE TEMPORARY TABLE t(c INT) ENGINE=InnoDB;
LOCK TABLES t AS a WRITE;
ALTER TABLE t ADD COLUMN c2 INT;
REPAIR TABLE t USE_FRM;

Leads to:

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f

mysqld: /test/10.5_dbg/sql/sql_base.cc:2354: int Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction.stmt.is_empty()' failed.

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f

Core was generated by `/test/MD210420-mariadb-10.5.3-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x7f07960dc700 (LWP 942624))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x00005583447e503d in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x0000558343f8ad7b in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:329
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f0794820801 in __GI_abort () at abort.c:79
#6  0x00007f079481039a in __assert_fail_base (fmt=0x7f07949977d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x558344947fd8 "thd->transaction.stmt.is_empty()", file=file@entry=0x558344947830 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2354, function=function@entry=0x55834494b080 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:92
#7  0x00007f0794810412 in __GI___assert_fail (assertion=assertion@entry=0x558344947fd8 "thd->transaction.stmt.is_empty()", file=file@entry=0x558344947830 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2354, function=function@entry=0x55834494b080 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x0000558343c5bac7 in Locked_tables_list::unlock_locked_tables (this=this@entry=0x7f0768818ed0, thd=thd@entry=0x7f0768815088) at /test/10.5_dbg/sql/sql_base.cc:2354
#9  0x0000558343c5bf5d in Locked_tables_list::unlink_all_closed_tables (this=this@entry=0x7f0768818ed0, thd=thd@entry=0x7f0768815088, lock=lock@entry=0x0, reopen_count=<optimized out>, reopen_count@entry=0) at /test/10.5_dbg/sql/sql_base.cc:2535
#10 0x0000558343e4364e in prepare_for_repair (thd=thd@entry=0x7f0768815088, table_list=table_list@entry=0x7f0768874168, check_opt=check_opt@entry=0x7f076881a330) at /test/10.5_dbg/sql/sql_admin.cc:262
#11 0x0000558343e4487d in mysql_admin_table (thd=thd@entry=0x7f0768815088, tables=tables@entry=0x7f0768874168, check_opt=check_opt@entry=0x7f076881a330, operator_name=operator_name@entry=0x558344cc2426 "repair", lock_type=lock_type@entry=TL_WRITE, org_open_for_modify=org_open_for_modify@entry=true, repair_table_use_frm=true, extra_open_options=32, prepare_func=0x558343e43383 <prepare_for_repair(THD*, TABLE_LIST*, HA_CHECK_OPT*)>, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x558343f98b3a <handler::ha_repair(THD*, st_ha_check_opt*)>, view_operator_func=0x558343ddd86f <view_repair(THD*, TABLE_LIST*, st_ha_check_opt*)>) at /test/10.5_dbg/sql/sql_admin.cc:598
#12 0x0000558343e47015 in Sql_cmd_repair_table::execute (this=<optimized out>, thd=0x7f0768815088) at /test/10.5_dbg/sql/sql_admin.cc:1407
#13 0x0000558343ce6422 in mysql_execute_command (thd=thd@entry=0x7f0768815088) at /test/10.5_dbg/sql/sql_parse.cc:5912
#14 0x0000558343cedf2b in mysql_parse (thd=thd@entry=0x7f0768815088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f07960db450, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7957
#15 0x0000558343cd9c45 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f0768815088, packet=packet@entry=0x7f0768867089 "", packet_length=packet_length@entry=22, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1839
#16 0x0000558343cd849b in do_command (thd=0x7f0768815088) at /test/10.5_dbg/sql/sql_parse.cc:1358
#17 0x0000558343e33415 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x7f07743c53a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1422
#18 0x0000558343e33744 in handle_one_connection (arg=arg@entry=0x7f07743c53a8) at /test/10.5_dbg/sql/sql_connect.cc:1319
#19 0x0000558344293fb0 in pfs_spawn_thread (arg=0x7f0793c45b08) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#20 0x00007f07955036db in start_thread (arg=0x7f07960dc700) at pthread_create.c:463
#21 0x00007f079490188f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.45 (dbg), 10.2.32 (dbg), 10.3.23 (dbg), 10.4.13 (dbg), 10.5.2 (dbg), 10.5.3 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.45 (opt), 10.2.32 (opt), 10.3.23 (opt), 10.4.13 (opt), 10.5.2 (opt), 10.5.3 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

Comment by Roel Van de Paar [ 2020-04-22 ]

svoj Hi! Would you mind having a look at this one? Thank you!

Comment by Sergey Vojtovich [ 2020-04-27 ]

serg, please review c2b3a4c253a76c1aaa6ef5d96bb7995afc3a572b.

Comment by Roel Van de Paar [ 2020-06-15 ]

Additional interesting testcase

USE test;
CREATE TABLE t (a INT PRIMARY KEY, b INT);
SET MAX_STATEMENT_TIME=0.001;
LOCK TABLE t WRITE;
ALTER TABLE t ALGORITHM=INPLACE, ADD d FLOAT;

Leads to:

10.5.4 4080e3acefd7e58d88c2f3539fb6a0fb359cf057

mysqld: /test/10.5_dbg/sql/sql_base.cc:2358: int Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction->stmt.is_empty()' failed.

10.5.4 4080e3acefd7e58d88c2f3539fb6a0fb359cf057

Core was generated by `/test/MD150620-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x14ca62157700 (LWP 2014139))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055d454fb64c6 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x000055d454758d60 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x000014ca6a87a801 in __GI_abort () at abort.c:79
#6  0x000014ca6a86a39a in __assert_fail_base (fmt=0x14ca6a9f17d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55d455121078 "thd->transaction->stmt.is_empty()", file=file@entry=0x55d4551208d0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55d455124140 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:92
#7  0x000014ca6a86a412 in __GI___assert_fail (assertion=assertion@entry=0x55d455121078 "thd->transaction->stmt.is_empty()", file=file@entry=0x55d4551208d0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55d455124140 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x000055d4544296dd in Locked_tables_list::unlock_locked_tables (this=this@entry=0x14ca48c18ed8, thd=thd@entry=0x14ca48c15088) at /test/10.5_dbg/sql/sql_base.cc:2358
#9  0x000055d454429b81 in Locked_tables_list::unlink_all_closed_tables (this=this@entry=0x14ca48c18ed8, thd=thd@entry=0x14ca48c15088, lock=lock@entry=0x0, reopen_count=<optimized out>, reopen_count@entry=0) at /test/10.5_dbg/sql/sql_base.cc:2540
#10 0x000055d45442bd60 in Locked_tables_list::reopen_tables (this=this@entry=0x14ca48c18ed8, thd=thd@entry=0x14ca48c15088, need_reopen=need_reopen@entry=false) at /test/10.5_dbg/sql/sql_base.cc:2636
#11 0x000055d454587d58 in mysql_alter_table (thd=thd@entry=0x14ca48c15088, new_db=new_db@entry=0x14ca48c19948, new_name=new_name@entry=0x14ca48c19d50, create_info=create_info@entry=0x14ca62155220, table_list=<optimized out>, table_list@entry=0x14ca48c741a8, alter_info=alter_info@entry=0x14ca62155150, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10966
#12 0x000055d454609a7a in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x14ca48c15088) at /test/10.5_dbg/sql/sql_alter.cc:532
#13 0x000055d4544b3860 in mysql_execute_command (thd=thd@entry=0x14ca48c15088) at /test/10.5_dbg/sql/sql_parse.cc:5951
#14 0x000055d4544bb15c in mysql_parse (thd=thd@entry=0x14ca48c15088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14ca62156350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7993
#15 0x000055d4544a7c60 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14ca48c15088, packet=packet@entry=0x14ca48c67089 "ALTER TABLE t ALGORITHM=INPLACE, ADD d FLOAT", packet_length=packet_length@entry=44, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1874
#16 0x000055d4544a643a in do_command (thd=0x14ca48c15088) at /test/10.5_dbg/sql/sql_parse.cc:1355
#17 0x000055d454601c47 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14ca4bd7a808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
#18 0x000055d454602363 in handle_one_connection (arg=arg@entry=0x14ca4bd7a808) at /test/10.5_dbg/sql/sql_connect.cc:1313
#19 0x000055d454a63902 in pfs_spawn_thread (arg=0x14ca69446c88) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#20 0x000014ca6b55d6db in start_thread (arg=0x14ca62157700) at pthread_create.c:463
#21 0x000014ca6a95b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.46 (dbg), 10.2.33 (dbg), 10.2.33 (opt), 10.3.24 (dbg), 10.5.4 (dbg), 10.5.4 (opt)

Bug confirmed not present in:
MariaDB: 10.1.46 (opt), 10.3.24 (opt), 10.4.14 (dbg), 10.4.14 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

Comment by Roel Van de Paar [ 2020-06-15 ]

Note to self; Unique ID's seen;

thd->transaction.stmt.is_empty()|SIGABRT|Locked_tables_list::unlock_locked_tables|Locked_tables_list::unlink_all_closed_tables|prepare_for_repair|mysql_admin_table
thd->transaction->stmt.is_empty()|SIGABRT|Locked_tables_list::unlock_locked_tables|Locked_tables_list::unlink_all_closed_tables|prepare_for_repair|mysql_admin_table
thd->transaction->stmt.is_empty()|SIGABRT|Locked_tables_list::unlock_locked_tables|Locked_tables_list::unlink_all_closed_tables|Locked_tables_list::reopen_tables|mysql_alter_table
thd->transaction->stmt.is_empty()|SIGABRT|Locked_tables_list::unlock_locked_tables|Locked_tables_list::unlink_all_closed_tables|Locked_tables_list::reopen_tables|mysql_create_or_drop_trigger
thd->transaction->stmt.is_empty()|SIGABRT|Locked_tables_list::unlock_locked_tables|Locked_tables_list::unlink_all_closed_tables|Locked_tables_list::reopen_tables|mysql_inplace_alter_table  # Alice' testcase

Comment by Roel Van de Paar [ 2020-06-15 ]

One more testcase to test fixes with

CREATE DATABASE test;
USE test;
CREATE TEMPORARY TABLE t (c1 INT) ENGINE=InnoDB;
LOCK TABLES t AS a READ, t AS b READ LOCAL;
OPTIMIZE LOCAL TABLE t;
REPAIR LOCAL TABLE t USE_FRM;

Comment by Roel Van de Paar [ 2020-06-30 ]

One additional test:

# mysqld options required for replay: --log-bin
USE test;
SET SQL_MODE='';
DROP TABLE t;
SET @@MAX_STATEMENT_TIME=0.0001;
CREATE TABLE t (a INT KEY, b TEXT) ROW_FORMAT=COMPACT ENGINE=InnoDB;
UPDATE t SET NAME='U+039B GREEK CAPITAL LETTER LAMDA' WHERE ujis=0xA6AB;
lock tables t write, t as t0 read, t as t2 read;
SET @@GLOBAL.OPTIMIZER_SWITCH="table_elimination=ON";
ALTER TABLE t ENGINE=InnoDB;
# Sporadic; keep repeating test till it crashes (usually 1-2 attempts) 

Leads to:

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

mysqld: /test/10.5_dbg/sql/sql_base.cc:2358: int Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction->stmt.is_empty()' failed.

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

Core was generated by `/test/MD250620-mariadb-10.5.5-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x14cf2d02d700 (LWP 2523825))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055579aad37d0 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x000055579a28c47a in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x000014cf2b30e801 in __GI_abort () at abort.c:79
#6  0x000014cf2b2fe39a in __assert_fail_base (fmt=0x14cf2b4857d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55579ac3e0d8 "thd->transaction->stmt.is_empty()", file=file@entry=0x55579ac3d930 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55579ac411a0 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:92
#7  0x000014cf2b2fe412 in __GI___assert_fail (assertion=assertion@entry=0x55579ac3e0d8 "thd->transaction->stmt.is_empty()", file=file@entry=0x55579ac3d930 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55579ac411a0 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x0000555799f5c899 in Locked_tables_list::unlock_locked_tables (this=this@entry=0x14cf09018ed8, thd=thd@entry=0x14cf09015088) at /test/10.5_dbg/sql/sql_base.cc:2358
#9  0x0000555799f5cd3d in Locked_tables_list::unlink_all_closed_tables (this=this@entry=0x14cf09018ed8, thd=thd@entry=0x14cf09015088, lock=lock@entry=0x0, reopen_count=<optimized out>, reopen_count@entry=0) at /test/10.5_dbg/sql/sql_base.cc:2540
#10 0x0000555799f5ef20 in Locked_tables_list::reopen_tables (this=this@entry=0x14cf09018ed8, thd=thd@entry=0x14cf09015088, need_reopen=need_reopen@entry=false) at /test/10.5_dbg/sql/sql_base.cc:2637
#11 0x000055579a0a8f71 in mysql_inplace_alter_table (thd=thd@entry=0x14cf09015088, table_list=0x14cf09074188, table=table@entry=0x14cf09180088, altered_table=altered_table@entry=0x14cf2d0289e0, ha_alter_info=ha_alter_info@entry=0x14cf2d028940, inplace_supported=inplace_supported@entry=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x14cf2d0297a0, alter_ctx=0x14cf2d02a630) at /test/10.5_dbg/sql/sql_table.cc:8177
#12 0x000055579a0b91f4 in mysql_alter_table (thd=thd@entry=0x14cf09015088, new_db=new_db@entry=0x14cf09019948, new_name=new_name@entry=0x14cf09019d50, create_info=create_info@entry=0x14cf2d02b220, table_list=<optimized out>, table_list@entry=0x14cf09074188, alter_info=alter_info@entry=0x14cf2d02b150, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10595
#13 0x000055579a13cf92 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x14cf09015088) at /test/10.5_dbg/sql/sql_alter.cc:532
#14 0x0000555799fe6d26 in mysql_execute_command (thd=thd@entry=0x14cf09015088) at /test/10.5_dbg/sql/sql_parse.cc:5953
#15 0x0000555799fee638 in mysql_parse (thd=thd@entry=0x14cf09015088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14cf2d02c350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7995
#16 0x0000555799fdb110 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14cf09015088, packet=packet@entry=0x14cf09067089 "ALTER TABLE t ENGINE=InnoDB", packet_length=packet_length@entry=27, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1874
#17 0x0000555799fd98ea in do_command (thd=0x14cf09015088) at /test/10.5_dbg/sql/sql_parse.cc:1355
#18 0x000055579a13515f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14cf0c0d9f08, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
#19 0x000055579a13587b in handle_one_connection (arg=arg@entry=0x14cf0c0d9f08) at /test/10.5_dbg/sql/sql_connect.cc:1313
#20 0x000055579a59811c in pfs_spawn_thread (arg=0x14cf29c46788) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#21 0x000014cf2bff16db in start_thread (arg=0x14cf2d02d700) at pthread_create.c:463
#22 0x000014cf2b3ef88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.46 (dbg), 10.2.33 (dbg), 10.2.33 (opt), 10.3.24 (dbg), 10.3.24 (opt), 10.4.14 (dbg), 10.5.5 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.46 (opt), 10.4.14 (opt), 10.5.5 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

Comment by Elena Stepanova [ 2020-07-11 ]

In addition to the same notorious debug assertion on all relevant versions, the test case below causes a crash on a non-debug build of 10.2-10.3 (but not 10.4-10.5).

--source include/have_innodb.inc
 
CREATE TABLE t1 (a INT) ENGINE=InnoDB;
SELECT * FROM t1;
SET SESSION MAX_SESSION_MEM_USED= @@max_session_mem_used + 1024;
LOCK TABLES t1 WRITE;
ALTER TABLE t1 FORCE;
 
# Cleanup
UNLOCK TABLES;
DROP TABLE t1;

10.2 737c3025

#3  <signal handler called>
#4  TABLE::default_column_bitmaps (this=0x0) at /data/src/10.2/sql/table.h:1478
#5  handler::ha_reset (this=0x7fc4f00b8630) at /data/src/10.2/sql/handler.cc:6083
#6  0x0000556280d49060 in THD::mark_tmp_table_as_free_for_reuse (this=this@entry=0x7fc4f00009a8, table=0x7fc4f00b7a98) at /data/src/10.2/sql/temporary_tables.cc:787
#7  0x0000556280d4a47e in THD::mark_tmp_tables_as_free_for_reuse (this=this@entry=0x7fc4f00009a8) at /data/src/10.2/sql/temporary_tables.cc:748
#8  0x0000556280bb26a7 in close_thread_tables (thd=thd@entry=0x7fc4f00009a8) at /data/src/10.2/sql/sql_base.cc:803
#9  0x0000556280bb3370 in Locked_tables_list::unlock_locked_tables (this=0x7fc4f0004258, thd=0x7fc4f00009a8) at /data/src/10.2/sql/sql_base.cc:2219
#10 0x0000556280bb4bd8 in Locked_tables_list::reopen_tables (this=this@entry=0x7fc4f0004258, thd=thd@entry=0x7fc4f00009a8, need_reopen=need_reopen@entry=false) at /data/src/10.2/sql/sql_base.cc:2494
#11 0x0000556280b3430e in mysql_inplace_alter_table (thd=thd@entry=0x7fc4f00009a8, table_list=0x7fc4f000f178, table=table@entry=0x7fc4f00a1f18, altered_table=altered_table@entry=0x7fc4f00b7a98, ha_alter_info=ha_alter_info@entry=0x7fc542e54400, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, alter_ctx=0x7fc542e54c60, target_mdl_request=0x7fc542e54490) at /data/src/10.2/sql/sql_table.cc:7585
#12 0x0000556280c8b181 in mysql_alter_table (thd=thd@entry=0x7fc4f00009a8, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x7fc542e55860, table_list=<optimized out>, table_list@entry=0x7fc4f000f178, alter_info=alter_info@entry=0x7fc542e557b0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9622
#13 0x0000556280cd7174 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7fc4f00009a8) at /data/src/10.2/sql/sql_alter.cc:333
#14 0x0000556280bfd38a in mysql_execute_command (thd=thd@entry=0x7fc4f00009a8) at /data/src/10.2/sql/sql_parse.cc:5964
#15 0x0000556280c0463a in mysql_parse (thd=thd@entry=0x7fc4f00009a8, rawbuf=<optimized out>, length=20, parser_state=parser_state@entry=0x7fc542e57620, 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:7733
#16 0x0000556280c06ec0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fc4f00009a8, packet=packet@entry=0x7fc4f0006cf9 "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:1824
#17 0x0000556280c07c80 in do_command (thd=0x7fc4f00009a8) at /data/src/10.2/sql/sql_parse.cc:1377
#18 0x0000556280cd4522 in do_handle_one_connection (connect=connect@entry=0x55628411dfb8) at /data/src/10.2/sql/sql_connect.cc:1336
#19 0x0000556280cd467d in handle_one_connection (arg=arg@entry=0x55628411dfb8) at /data/src/10.2/sql/sql_connect.cc:1241
#20 0x00005562812964d1 in pfs_spawn_thread (arg=0x5562840b5b98) at /data/src/10.2/storage/perfschema/pfs.cc:1869
#21 0x00007fc549a2c4a4 in start_thread (arg=0x7fc542e58700) at pthread_create.c:456
#22 0x00007fc548aaad0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

The proposed patch fixes it.

Raising the priority of the JIRA item since it affects tests and already has a patch for review.

Comment by Roel Van de Paar [ 2020-09-26 ]

CREATE TABLE t (c INT);
INSERT INTO t VALUES(1);
SET max_session_mem_used=8192;
LOCK TABLE t WRITE;
CREATE TRIGGER tr BEFORE INSERT ON t FOR EACH ROW INSERT INTO t VALUES(2);

Leads to:

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

mysqld: /test/10.5_dbg/sql/sql_base.cc:2358: int Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction->stmt.is_empty()' failed.

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

Core was generated by `/test/MD150920-mariadb-10.5.6-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x154a806bf700 (LWP 3498484))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x00005641eff3285a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
#2  0x00005641ef6f93a9 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x0000154a7e9558b1 in __GI_abort () at abort.c:79
#6  0x0000154a7e94542a in __assert_fail_base (fmt=0x154a7eacca38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5641f009e278 "thd->transaction->stmt.is_empty()", file=file@entry=0x5641f009dad0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x5641f00a1340 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:92
#7  0x0000154a7e9454a2 in __GI___assert_fail (assertion=assertion@entry=0x5641f009e278 "thd->transaction->stmt.is_empty()", file=file@entry=0x5641f009dad0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x5641f00a1340 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x00005641ef3c0df9 in Locked_tables_list::unlock_locked_tables (this=this@entry=0x154a5c019058, thd=thd@entry=0x154a5c015088) at /test/10.5_dbg/sql/sql_base.cc:2358
#9  0x00005641ef3c129d in Locked_tables_list::unlink_all_closed_tables (this=this@entry=0x154a5c019058, thd=thd@entry=0x154a5c015088, lock=lock@entry=0x0, reopen_count=<optimized out>, reopen_count@entry=1) at /test/10.5_dbg/sql/sql_base.cc:2540
#10 0x00005641ef3c3525 in Locked_tables_list::reopen_tables (this=this@entry=0x154a5c019058, thd=thd@entry=0x154a5c015088, need_reopen=need_reopen@entry=false) at /test/10.5_dbg/sql/sql_base.cc:2665
#11 0x00005641ef52bdd8 in mysql_create_or_drop_trigger (thd=thd@entry=0x154a5c015088, tables=<optimized out>, create=create@entry=true) at /test/10.5_dbg/sql/sql_trigger.cc:604
#12 0x00005641ef44b305 in mysql_execute_command (thd=thd@entry=0x154a5c015088) at /test/10.5_dbg/sql/sql_parse.cc:5780
#13 0x00005641ef453324 in mysql_parse (thd=thd@entry=0x154a5c015088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x154a806be350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
#14 0x00005641ef43fd54 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x154a5c015088, packet=packet@entry=0x154a5c067089 "CREATE TRIGGER tr BEFORE INSERT ON t FOR EACH ROW INSERT INTO t VALUES(2)", packet_length=packet_length@entry=73, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1867
#15 0x00005641ef43e53e in do_command (thd=0x154a5c015088) at /test/10.5_dbg/sql/sql_parse.cc:1348
#16 0x00005641ef59d893 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x154a5f4d4808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
#17 0x00005641ef59dfb7 in handle_one_connection (arg=arg@entry=0x154a5f4d4808) at /test/10.5_dbg/sql/sql_connect.cc:1312
#18 0x00005641efa085c2 in pfs_spawn_thread (arg=0x154a7d446508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#19 0x0000154a7f6386db in start_thread (arg=0x154a806bf700) at pthread_create.c:463
#20 0x0000154a7ea36a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.47 (dbg), 10.2.34 (dbg), 10.3.25 (dbg), 10.4.15 (dbg), 10.5.6 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.47 (opt), 10.2.34 (opt), 10.3.25 (opt), 10.4.15 (opt), 10.5.6 (opt), 10.6.0 (dbg), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.49 (dbg), 5.6.49 (opt), 5.7.31 (dbg), 5.7.31 (opt), 8.0.21 (dbg), 8.0.21 (opt)

Comment by Roel Van de Paar [ 2020-09-26 ]

The testcase by Elena also crashes other versions now inc 10.5 dbg

CREATE TABLE t1 (a INT) ENGINE=InnoDB;
SELECT * FROM t1;
SET SESSION MAX_SESSION_MEM_USED= @@max_session_mem_used + 1024;
LOCK TABLES t1 WRITE;
ALTER TABLE t1 FORCE;

Leads to:

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

mysqld: /test/10.5_dbg/sql/sql_base.cc:2358: int Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction->stmt.is_empty()' failed.

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

Core was generated by `/test/MD150920-mariadb-10.5.6-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x14b373767700 (LWP 3509774))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055edff51585a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
#2  0x000055edfecdc3a9 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x000014b3719fd8b1 in __GI_abort () at abort.c:79
#6  0x000014b3719ed42a in __assert_fail_base (fmt=0x14b371b74a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55edff681278 "thd->transaction->stmt.is_empty()", file=file@entry=0x55edff680ad0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55edff684340 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:92
#7  0x000014b3719ed4a2 in __GI___assert_fail (assertion=assertion@entry=0x55edff681278 "thd->transaction->stmt.is_empty()", file=file@entry=0x55edff680ad0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55edff684340 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x000055edfe9a3df9 in Locked_tables_list::unlock_locked_tables (this=this@entry=0x14b34f419058, thd=thd@entry=0x14b34f415088) at /test/10.5_dbg/sql/sql_base.cc:2358
#9  0x000055edfe9a429d in Locked_tables_list::unlink_all_closed_tables (this=this@entry=0x14b34f419058, thd=thd@entry=0x14b34f415088, lock=lock@entry=0x0, reopen_count=<optimized out>, reopen_count@entry=0) at /test/10.5_dbg/sql/sql_base.cc:2540
#10 0x000055edfe9a647e in Locked_tables_list::reopen_tables (this=this@entry=0x14b34f419058, thd=thd@entry=0x14b34f415088, need_reopen=need_reopen@entry=false) at /test/10.5_dbg/sql/sql_base.cc:2637
#11 0x000055edfeaf39f4 in mysql_inplace_alter_table (thd=thd@entry=0x14b34f415088, table_list=0x14b34f474178, table=table@entry=0x14b34f452088, altered_table=altered_table@entry=0x14b3737633d0, ha_alter_info=ha_alter_info@entry=0x14b373763330, target_mdl_request=target_mdl_request@entry=0x14b3737637a0, alter_ctx=0x14b373764630) at /test/10.5_dbg/sql/sql_table.cc:8144
#12 0x000055edfeb03cc6 in mysql_alter_table (thd=thd@entry=0x14b34f415088, new_db=new_db@entry=0x14b34f419ac8, new_name=new_name@entry=0x14b34f419ed0, create_info=create_info@entry=0x14b373765220, table_list=<optimized out>, table_list@entry=0x14b34f474178, alter_info=alter_info@entry=0x14b373765150, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10571
#13 0x000055edfeb88636 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x14b34f415088) at /test/10.5_dbg/sql/sql_alter.cc:534
#14 0x000055edfea2e9b0 in mysql_execute_command (thd=thd@entry=0x14b34f415088) at /test/10.5_dbg/sql/sql_parse.cc:5952
#15 0x000055edfea36324 in mysql_parse (thd=thd@entry=0x14b34f415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b373766350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
#16 0x000055edfea22d54 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b34f415088, packet=packet@entry=0x14b34f467089 "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 /test/10.5_dbg/sql/sql_parse.cc:1867
#17 0x000055edfea2153e in do_command (thd=0x14b34f415088) at /test/10.5_dbg/sql/sql_parse.cc:1348
#18 0x000055edfeb80893 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14b3528d4808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
#19 0x000055edfeb80fb7 in handle_one_connection (arg=arg@entry=0x14b3528d4808) at /test/10.5_dbg/sql/sql_connect.cc:1312
#20 0x000055edfefeb5c2 in pfs_spawn_thread (arg=0x14b370446508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#21 0x000014b3726e06db in start_thread (arg=0x14b373767700) at pthread_create.c:463
#22 0x000014b371adea3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.47 (dbg), 10.2.34 (dbg), 10.2.34 (opt), 10.3.25 (dbg), 10.3.25 (opt), 10.4.15 (dbg), 10.5.6 (dbg), 10.6.0 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.47 (opt), 10.4.15 (opt), 10.5.6 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.49 (dbg), 5.6.49 (opt), 5.7.31 (dbg), 5.7.31 (opt), 8.0.21 (dbg), 8.0.21 (opt)

Comment by Roel Van de Paar [ 2020-10-17 ]

Highly sporadic testcase (CLI replay tested). Note CREATE TABLEs are InnoDB.

# Repeat 4000+ times to reproduce bug
SET max_statement_time = 0.001;
CREATE TABLE t2 (pk VARCHAR (16) PRIMARY KEY, fk VARCHAR (10));
CREATE TEMPORARY TABLE t3 LIKE t2;
ALTER TABLE t3 ENGINE=Aria;
LOCK TABLES t2 AS a2 READ, t3 AS a6 LOW_PRIORITY WRITE, t2 AS a7 WRITE;
FLUSH no_write_to_binlog TABLES t2;

Leads to:

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

Core was generated by `/test/MD150920-mariadb-10.5.6-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x14726e589700 (LWP 3003050))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055b46554685a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
#2  0x000055b464d0d3a9 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x000014726c81f8b1 in __GI_abort () at abort.c:79
#6  0x000014726c80f42a in __assert_fail_base (fmt=0x14726c996a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55b4656b2278 "thd->transaction->stmt.is_empty()", file=file@entry=0x55b4656b1ad0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55b4656b5340 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:92
#7  0x000014726c80f4a2 in __GI___assert_fail (assertion=assertion@entry=0x55b4656b2278 "thd->transaction->stmt.is_empty()", file=file@entry=0x55b4656b1ad0 "/test/10.5_dbg/sql/sql_base.cc", line=line@entry=2358, function=function@entry=0x55b4656b5340 <Locked_tables_list::unlock_locked_tables(THD*)::__PRETTY_FUNCTION__> "int Locked_tables_list::unlock_locked_tables(THD*)") at assert.c:101
#8  0x000055b4649d4df9 in Locked_tables_list::unlock_locked_tables (this=this@entry=0x14724a419058, thd=thd@entry=0x14724a415088) at /test/10.5_dbg/sql/sql_base.cc:2358
#9  0x000055b4649d529d in Locked_tables_list::unlink_all_closed_tables (this=this@entry=0x14724a419058, thd=thd@entry=0x14724a415088, lock=lock@entry=0x0, reopen_count=<optimized out>, reopen_count@entry=2) at /test/10.5_dbg/sql/sql_base.cc:2540
#10 0x000055b4649d7525 in Locked_tables_list::reopen_tables (this=this@entry=0x14724a419058, thd=thd@entry=0x14724a415088, need_reopen=need_reopen@entry=false) at /test/10.5_dbg/sql/sql_base.cc:2665
#11 0x000055b4649d771e in close_cached_tables (thd=thd@entry=0x14724a415088, tables=tables@entry=0x14724a474188, wait_for_refresh=wait_for_refresh@entry=true, timeout=86400) at /test/10.5_dbg/sql/sql_base.cc:404
#12 0x000055b464be7152 in reload_acl_and_cache (thd=thd@entry=0x14724a415088, options=4, tables=tables@entry=0x14724a474188, write_to_binlog=write_to_binlog@entry=0x14726e587d70) at /test/10.5_dbg/sql/sql_reload.cc:335
#13 0x000055b464a5e3c2 in mysql_execute_command (thd=thd@entry=0x14724a415088) at /test/10.5_dbg/sql/sql_parse.cc:5424
#14 0x000055b464a67324 in mysql_parse (thd=thd@entry=0x14724a415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14726e588350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
#15 0x000055b464a53d54 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14724a415088, packet=packet@entry=0x14724a467089 "FLUSH no_write_to_binlog TABLES t2", packet_length=packet_length@entry=34, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1867
#16 0x000055b464a5253e in do_command (thd=0x14724a415088) at /test/10.5_dbg/sql/sql_parse.cc:1348
#17 0x000055b464bb1893 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14724d4d4808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
#18 0x000055b464bb1fb7 in handle_one_connection (arg=arg@entry=0x14724d4d4808) at /test/10.5_dbg/sql/sql_connect.cc:1312
#19 0x000055b46501c5c2 in pfs_spawn_thread (arg=0x14726b446508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#20 0x000014726d5026db in start_thread (arg=0x14726e589700) at pthread_create.c:463
#21 0x000014726c900a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Sergei Golubchik [ 2020-10-23 ]

note to self: the commit c2b3a4c253a76c1aaa6ef5d96bb7995afc3a572b maikes rocksdb.kill to fail

Comment by Sergei Golubchik [ 2020-10-26 ]

it seems like we generally do unlock automatically when there are no more locked tables.

Comment by Roel Van de Paar [ 2020-10-27 ]

10.6 dbg stack looks similar, however there is something interesting on 10.6 opt builds:

10.6.0 5d4599f9750140f92cfdbbe4d292ae1b8dd456f8 (Optimized)

10.6.0>CREATE TABLE t1 (a INT) ENGINE=InnoDB;
Query OK, 0 rows affected (0.010 sec)
10.6.0>SELECT * FROM t1;
Empty set (0.001 sec)
10.6.0>SET SESSION MAX_SESSION_MEM_USED= @@max_session_mem_used + 1024;
Query OK, 0 rows affected (0.000 sec)
10.6.0>LOCK TABLES t1 WRITE;
Query OK, 0 rows affected (0.000 sec)
10.6.0>ALTER TABLE t1 FORCE;
ERROR 1317 (70100): Query execution was interrupted

Consistently reproducible. Re-opening the CLI and re-executing the same gives:

10.6.0>ALTER TABLE t1 FORCE;
Query OK, 0 rows affected (0.017 sec)
Records: 0  Duplicates: 0  Warnings: 0
10.6.0>ALTER TABLE t1 FORCE;
Query OK, 0 rows affected (0.019 sec)
Records: 0  Duplicates: 0  Warnings: 0

Comment by Michael Widenius [ 2021-05-26 ]

The same bug also affects LOCK TABLES ; CREATE TRIGGER:

CREATE TABLE t1 (id int(11)) ENGINE=InnoDB;
LOCK TABLES t1 WRITE;
SET max_statement_time= 0.0001;
--error 0,1969
--disable_warnings
CREATE TRIGGER tr16 AFTER UPDATE ON t1 FOR EACH ROW INSERT INTO t1 VALUES (1);
--enable_warnings
SET max_statement_time= default;
DROP TRIGGER IF EXISTS trg16;
DROP TABLE t1;

Comment by Michael Widenius [ 2021-05-26 ]

Fixed

The problem was that when LOCK TABLES where unwinded as part of
a killed connection, unlink_all_closed_tables() did not like that
there was uncommitted transactions.
Fixed by doing a rollback of any open transaction in this particular case.

Generated at Thu Feb 08 08:38:49 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.