[MDEV-32272] lock_release_on_prepare_try() does not release lock if supremum bit is set along with other bits set in lock's bitmap - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.5, 10.6, 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL), 11.1(EOL), 11.2(EOL), 11.3(EOL)
Fix Version/s: 10.6.16, 10.10.7, 10.11.6, 11.0.4, 11.1.3
Component/s: Locking, Replication, Storage Engine - InnoDB, XA
Labels:
- affects-tests

Description

Seems related to MDEV-30941. While it is not caused by MDEV-31949, it causes interference with testing of MDEV-31949 and re-testing of ~~MDEV-32257~~.

--source include/have_innodb.inc

CREATE TABLE t2 (t1_a INT,b INT) ENGINE=InnoDB;

SET SESSION pseudo_slave_mode=1;

CREATE TABLE t1 (a INT KEY,b LONG) ENGINE=InnoDB;

XA START 'a';

INSERT INTO t1 SELECT * FROM t1;

INSERT INTO t2 VALUES (0,0);

XA END 'a';

XA PREPARE 'a';

DROP TABLE t1,t2;

The outcomes for the final query differs significantly from version to version:

10.4.32 47f0135d7aba57d160d1d95ff7f1f6b7bb07c2fb (Optimized + Debug)
10.4.32>DROP TABLE t1,t2;
ERROR 1399 (XAE07): XAER_RMFAIL: The command cannot be executed when global transaction is in the PREPARED state

10.5.23 6b343de8ef51e4c92f0ea2bf62f27f0aab32204d (Optimized)
10.5.23-opt>DROP TABLE t1,t2;
Query OK, 0 rows affected (0.008 sec)

10.6.16 076df87b4c1dc5123d66600b82201050c45aa9d9 (Debug)
10.6.16-dbg>DROP TABLE t1,t2;
ERROR 2013 (HY000): Lost connection to server during query

10.9.8 3e0009dc3a771e4dbf2fa4a4cf87e750453fb2eb (Debug)
10.9.8-dbg>DROP TABLE t1,t2;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

10.10+ versions all show the ERROR 1205 Lock wait timeout.
An example of the process list during before the timeout happens:

10.9.8 3e0009dc3a771e4dbf2fa4a4cf87e750453fb2eb (Debug)
10.9.8-dbg>SHOW PROCESSLIST;
+----+------+-----------+------+---------+------+----------------+------------------+----------+
\| Id \| User \| Host \| db \| Command \| Time \| State \| Info \| Progress \|
+----+------+-----------+------+---------+------+----------------+------------------+----------+
\| 4 \| root \| localhost \| test \| Query \| 29 \| closing tables \| DROP TABLE t1,t2 \| 0.000 \|
\| 5 \| root \| localhost \| test \| Query \| 0 \| starting \| SHOW PROCESSLIST \| 0.000 \|
+----+------+-----------+------+---------+------+----------------+------------------+----------+
2 rows in set (0.000 sec)

MySQL 5.5 to 5.7 show the ERROR 1399:

MySQL 5.7.40 c4f63caa8d9f30b2850672291e0ad0928dd89d0e (Debug) and MS 5.5, MS 5.6
5.7.40-dbg>DROP TABLE t1,t2;
ERROR 1399 (XAE07): XAER_RMFAIL: The command cannot be executed when global transaction is in the PREPARED state

MySQL 8 is different again, it waits much longer and the process list shows:

MySQL 8.0.33 ea7087d885006918ad54458e7aad215b1650312c (Optimized)
mysql> SHOW PROCESSLIST;
+----+-----------------+-----------+------+---------+------+---------------------------------+------------------+
\| Id \| User \| Host \| db \| Command \| Time \| State \| Info \|
+----+-----------------+-----------+------+---------+------+---------------------------------+------------------+
\| 5 \| event_scheduler \| localhost \| NULL \| Daemon \| 476 \| Waiting on empty queue \| NULL \|
\| 9 \| root \| localhost \| test \| Query \| 474 \| Waiting for table metadata lock \| DROP TABLE t1,t2 \|
\| 10 \| root \| localhost \| test \| Query \| 0 \| init \| SHOW PROCESSLIST \|
+----+-----------------+-----------+------+---------+------+---------------------------------+------------------+
3 rows in set (0.00 sec)

The stacks for the crash on 10.6 opt/dbg:

10.6.16 076df87b4c1dc5123d66600b82201050c45aa9d9 (Optimized)
2023-09-28 09:49:54 0x149808da3640 InnoDB: Assertion failure in file /test/10.6_opt/storage/innobase/dict/dict0dict.cc line 1862
InnoDB: Failing assertion: table->n_rec_locks == 0

10.6.16 076df87b4c1dc5123d66600b82201050c45aa9d9 (Optimized)
Core was generated by `/test/MD270923-mariadb-10.6.16-linux-x86_64-opt/bin/mariadbd --no-defaults --co'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22643216102976)
at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x149808da3640 (LWP 4001869))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22643216102976) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22643216102976) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22643216102976, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x0000149813642476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x00001498136287f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x00005627b9753f5f in ut_dbg_assertion_failed (expr=expr@entry=0x5627ba412374 "table->n_rec_locks == 0", file=file@entry=0x5627ba412390 "/test/10.6_opt/storage/innobase/dict/dict0dict.cc", line=line@entry=1862) at /test/10.6_opt/storage/innobase/ut/ut0dbg.cc:60
#6 0x00005627b9760a48 in dict_sys_t::remove (this=0x5627baa0a500 <dict_sys>, table=table@entry=0x1497a401f520, lru=lru@entry=false, keep=keep@entry=false) at /test/10.6_opt/storage/innobase/dict/dict0dict.cc:1862
#7 0x00005627b9f9e214 in trx_t::commit (this=this@entry=0x14980a05d180, deleted=std::vector of length 0, capacity 0) at /test/10.6_opt/storage/innobase/dict/drop.cc:276
#8 0x00005627b9e329d4 in ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /test/10.6_opt/storage/innobase/handler/ha_innodb.cc:13782
#9 0x00005627b9af2245 in hton_drop_table (hton=<optimized out>, path=<optimized out>) at /test/10.6_opt/sql/handler.cc:573
#10 0x00005627b9af8bb9 in ha_delete_table (thd=thd@entry=0x1497a4000c68, hton=hton@entry=0x5627bbbbb658, path=path@entry=0x149808da1160 "./test/t1", db=db@entry=0x149808da0f50, alias=alias@entry=0x149808da0f60, generate_warning=generate_warning@entry=true) at /test/10.6_opt/sql/handler.cc:3163
#11 0x00005627b9942cbe in mysql_rm_table_no_locks (thd=0x1497a4000c68, tables=<optimized out>, current_db=<optimized out>, ddl_log_state=<optimized out>, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_view=<optimized out>, drop_sequence=<optimized out>, dont_log_query=<optimized out>, dont_free_locks=<optimized out>) at /test/10.6_opt/sql/sql_table.cc:1464
#12 0x00005627b994425c in mysql_rm_table (thd=thd@entry=0x1497a4000c68, tables=tables@entry=0x1497a40109c8, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_sequence=<optimized out>, dont_log_query=dont_log_query@entry=false) at /test/10.6_opt/sql/sql_table.cc:1041
#13 0x00005627b98a719a in mysql_execute_command (thd=0x1497a4000c68, is_called_from_prepared_stmt=<optimized out>) at /test/10.6_opt/sql/sql_parse.cc:4978
#14 0x00005627b98ab6e6 in mysql_parse (thd=0x1497a4000c68, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /test/10.6_opt/sql/sql_parse.cc:8050
#15 0x00005627b98ade85 in dispatch_command (command=COM_QUERY, thd=0x1497a4000c68, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /test/10.6_opt/sql/sql_parse.cc:1995
#16 0x00005627b98afbf0 in do_command (thd=0x1497a4000c68, blocking=blocking@entry=true) at /test/10.6_opt/sql/sql_parse.cc:1409
#17 0x00005627b99c024f in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /test/10.6_opt/sql/sql_connect.cc:1416
#18 0x00005627b99c059d in handle_one_connection (arg=arg@entry=0x5627bc0317c8) at /test/10.6_opt/sql/sql_connect.cc:1318
#19 0x00005627b9d724f1 in pfs_spawn_thread (arg=0x5627bbfc1e28) at /test/10.6_opt/storage/perfschema/pfs.cc:2201
#20 0x0000149813694b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#21 0x0000149813726a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

10.6.16 076df87b4c1dc5123d66600b82201050c45aa9d9 (Debug)
2023-09-28 10:04:17 0x152fa0953640 InnoDB: Assertion failure in file /test/10.6_dbg/storage/innobase/dict/dict0dict.cc line 1862
InnoDB: Failing assertion: table->n_rec_locks == 0

10.6.16 076df87b4c1dc5123d66600b82201050c45aa9d9 (Debug)
Core was generated by `/test/MD270923-mariadb-10.6.16-linux-x86_64-dbg/bin/mariadbd --no-defaults --co'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=23294301779520)
at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x152fa0953640 (LWP 2586101))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=23294301779520) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=23294301779520) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=23294301779520, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x0000152fb6c42476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x0000152fb6c287f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x000055e0d4e591a4 in ut_dbg_assertion_failed (expr=expr@entry=0x55e0d54838a4 "table->n_rec_locks == 0", file=file@entry=0x55e0d5483988 "/test/10.6_dbg/storage/innobase/dict/dict0dict.cc", line=line@entry=1862) at /test/10.6_dbg/storage/innobase/ut/ut0dbg.cc:60
#6 0x000055e0d4f0ba5b in dict_sys_t::remove (this=0x55e0d5a95a00 <dict_sys>, table=table@entry=0x152f6401d548, lru=lru@entry=false, keep=keep@entry=false) at /test/10.6_dbg/storage/innobase/dict/dict0dict.cc:1862
#7 0x000055e0d4f3b9e9 in trx_t::commit (this=this@entry=0x152fa1956180, deleted=std::vector of length 0, capacity 0) at /test/10.6_dbg/storage/innobase/dict/drop.cc:276
#8 0x000055e0d4c55c54 in ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:13782
#9 0x000055e0d48ba4e1 in hton_drop_table (hton=<optimized out>, path=<optimized out>) at /test/10.6_dbg/sql/handler.cc:573
#10 0x000055e0d48c2f5f in ha_delete_table (thd=thd@entry=0x152f64000d58, hton=hton@entry=0x55e0d7edfb28, path=path@entry=0x152fa09517b0 "./test/t1", db=db@entry=0x152fa09515a0, alias=alias@entry=0x152fa09515b0, generate_warning=generate_warning@entry=true) at /test/10.6_dbg/sql/handler.cc:3163
#11 0x000055e0d46b6d20 in mysql_rm_table_no_locks (thd=thd@entry=0x152f64000d58, tables=tables@entry=0x152f64013388, current_db=current_db@entry=0x152f64000df8, ddl_log_state=0x152fa09515d0, ddl_log_state@entry=0x0, if_exists=if_exists@entry=false, drop_temporary=drop_temporary@entry=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /test/10.6_dbg/sql/sql_table.cc:1464
#12 0x000055e0d46b8bb4 in mysql_rm_table (thd=thd@entry=0x152f64000d58, tables=tables@entry=0x152f64013388, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_sequence=<optimized out>, dont_log_query=dont_log_query@entry=false) at /test/10.6_dbg/sql/sql_table.cc:1041
#13 0x000055e0d460287d in mysql_execute_command (thd=thd@entry=0x152f64000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.6_dbg/sql/sql_parse.cc:4978
#14 0x000055e0d4607164 in mysql_parse (thd=thd@entry=0x152f64000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x152fa09521f0) at /test/10.6_dbg/sql/sql_parse.cc:8050
#15 0x000055e0d46094da in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x152f64000d58, packet=packet@entry=0x152f6400af29 "DROP TABLE t1,t2", packet_length=packet_length@entry=16, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:241
#16 0x000055e0d460b5f7 in do_command (thd=0x152f64000d58, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1409
#17 0x000055e0d474a1fd in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55e0d83b4fa8, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1416
#18 0x000055e0d474a4f2 in handle_one_connection (arg=arg@entry=0x55e0d83b4fa8) at /test/10.6_dbg/sql/sql_connect.cc:1318
#19 0x000055e0d4b9608c in pfs_spawn_thread (arg=0x55e0d8399708) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#20 0x0000152fb6c94b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#21 0x0000152fb6d26a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Attachments

Issue Links

blocks

MDEV-31949 slow parallel replication of user xa

Stalled

MDEV-32257 Assertion `thd->is_killed()' failed in XID_cache_element::acquired_to_recovered (opt) or acquire_xid (dbg) on XA ROLLBACK or XA COMMIT

Closed

is caused by

MDEV-26682 slave lock timeout with xa and gap locks

Closed

MDEV-30165 X-lock on supremum for prepared transaction for RR

Closed

is duplicated by

MDEV-32353 lock_release_on_prepare_try() does not release lock if supremum bit is set along with other bits set in lock's bitmap

Closed

relates to

MDEV-30941 ASAN: heap-use-after-free in std::__atomic_base from trx_t::commit_tables on XA COMMIT with pseudo_slave_mode enabled

Confirmed

MDEV-32262 InnoDB: Failing assertion: m_prebuilt->trx == thd_to_trx(m_user_thd) in ha_innobase::change_active_index

Confirmed

MDEV-32471 Backport MDEV-32272 test cases from 10.6 to 10.5

Open

(3 relates to)

Activity

People

Assignee:: Vladislav Lesin

Reporter:: Roel Van de Paar

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2023-09-28 00:13

Updated:: 2023-10-17 12:01

Resolved:: 2023-10-13 14:04

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.