[MDEV-28709] unexpected X lock on Supremum in READ COMMITTED - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.5.16
Fix Version/s: 10.5.18, 10.6.11, 10.7.7, 10.8.6, 10.9.4, 10.10.2, 10.11.1
Component/s: Replication, Storage Engine - InnoDB
Labels:
- XA

Description

Affects/is observed on 821808c45dd

Transaction that update,insert,delete a distinctive single record specified with a PK value
should not have any gap lock. E.g such one as call foo1(); where the table and procedure
are defined as follows

CREATE TABLE `t2_text` (

  `a` int(11) NOT NULL,

  `b` int(11) DEFAULT NULL,

  `c` text DEFAULT NULL,

  PRIMARY KEY (`a`)

) ENGINE=InnoDB

create procedure foo1()

begin

     declare av int;

     declare ni int;

     declare mk int;

     declare u0,u1,d int;

     declare skip_max int;

     set av = ceil(rand()*100);

     set ni = ceil(rand()*10);

     set skip_max = 2;

     set d = av + mod(ceil(rand()*100), skip_max*ni);

     set u0 = av + mod(ceil(rand()*100), skip_max*ni);

     set u1 = av + mod(ceil(rand()*100), skip_max*ni);

     while (ni > 0) do

       set mk = mod(ceil(rand()*100),4);

       replace into t2_text values (av, av, repeat('a', mk*1024));

       set ni = ni - 1;

       set av = av + 1 + mod(ceil(rand()*100), skip_max);

     end while;

     delete from t2_text where a = d;

     update t2_text set a=u1,b=u1 where a = u0;

end|

delimiter ;

However a X lock on Supremum record appears when the above `call foo1()` runs concurrently, like

--connection one

--send \

     select sleep(0.1);xa start '1'; call foo1(); xa end '1'; xa prepare '1'; select sleep(0.05); xa commit '1'; select sleep(0.1);

--connection two

--send \

     select sleep(0.1);xa start '2'; call foo1(); xa end '2'; xa prepare '2'; select sleep(0.05); xa commit '2'; select sleep(0.1);

so an assert, see the diff file attached, fires after few repeats.

It also survives ~~MDEV-26682~~ commit's action to clear the user XA out of gap locks.
The latter, as it was in ~~MDEV-26682~~ context, may have as a consequence seemingly non-conflicting XA transactions to become actually conflicting.
when they replayed on slave.

The attached diff suggests how to fix this though its idea is merely to work around xa replication issues, and not possible
isolation ones (when the presence of X on supremum indeed 'unexpected' and can't be justified).

(Edited to remove unnecessary Unique constraint from `b`)

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

MDEV-28709_x_sup.diff
2022-05-31 12:50
0.8 kB
Andrei Elkin
MDEV-28709-stable.test
2022-06-24 14:54
2 kB
Vladislav Lesin

Issue Links

is blocked by

MDEV-29575 Access to innodb_trx, innodb_locks and innodb_lock_waits along with detached XA's can cause SIGSEGV

Closed

relates to

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

Closed

MDEV-17814 Server crashes in is_current_stmt_binlog_format_row

Open

MDEV-26682 slave lock timeout with xa and gap locks

Closed

Activity

Ascending order - Click to sort in descending order

View 7 older comments

Vladislav Lesin added a comment - 2022-07-07 14:05

Some thoughts about testing. We need some tool to test isolation levels to prevent the cases like ~~MDEV-27025~~, when we released the fix, but it caused ~~MDEV-27992~~, which was reported after the release.

Marko gave me some hint for possible testing method: https://aphyr.com/posts/327-call-me-maybe-mariadb-galera-cluster. The general idea is to generate some operations on some limited amount of rows to have some concurrency, and then check data consistency.

This method does not work for all isolation levels, and even does not work for some kinds of queries. For example, here was shown, that the initial test was expected to cause data inconsistency for single-node RR level. Even if some transaction works in RR level, locking reads and writes work in RC mode.

But it's still can be used for some particular cases, for example Serializable testing, and this test can be a starting point for it.

One more interesting project is here. This can also be used as a starting point, it can give the idea what to test, but the initial tests does not involve some concurrency related operations, like pages splitting or purging.

Vladislav Lesin added a comment - 2022-07-07 14:05 Some thoughts about testing. We need some tool to test isolation levels to prevent the cases like MDEV-27025 , when we released the fix, but it caused MDEV-27992 , which was reported after the release. Marko gave me some hint for possible testing method: https://aphyr.com/posts/327-call-me-maybe-mariadb-galera-cluster . The general idea is to generate some operations on some limited amount of rows to have some concurrency, and then check data consistency. This method does not work for all isolation levels, and even does not work for some kinds of queries. For example, here was shown, that the initial test was expected to cause data inconsistency for single-node RR level. Even if some transaction works in RR level, locking reads and writes work in RC mode. But it's still can be used for some particular cases, for example Serializable testing, and this test can be a starting point for it. One more interesting project is here . This can also be used as a starting point, it can give the idea what to test, but the initial tests does not involve some concurrency related operations, like pages splitting or purging.

Matthias Leich added a comment - 2022-08-29 17:43 - edited

Preliminary result of RQG testing on

origin/bb-10.5-MDEV-28709-sup_X_lock d2b334aaa7656e7fa41868536ae3c65df94db470 2022-08-29T18:17:04+03:00

# 2022-08-29T15:39:56 [1054959] | [rr 1057634 252092]mysqld: /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc:4257: void lock_release_on_prepare(trx_t*): Assertion `lock->trx->isolation_level > 1 || !lock_rec_get_nth_bit(lock, 1U)' failed.

pluto:/data/results/1661787227/TBR-1590$ _RR_TRACE_DIR=./1/rr/ rr replay

# 2022-08-29T15:39:56 [1054959] | Thread 3 (Thread 1057634.1061052):

# 2022-08-29T15:39:56 [1054959] | #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

# 2022-08-29T15:39:56 [1054959] | #1  0x000073d1297eb859 in __GI_abort () at abort.c:79

# 2022-08-29T15:39:56 [1054959] | #2  0x000073d1297eb729 in __assert_fail_base (fmt=0x73d129981588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564a259c53a0 "lock->trx->isolation_level > 1 || !lock_rec_get_nth_bit(lock, 1U)", file=0x564a259c02e0 "/data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc", line=4257, function=<optimized out>) at assert.c:92

# 2022-08-29T15:39:56 [1054959] | #3  0x000073d1297fcf36 in __GI___assert_fail (assertion=0x564a259c53a0 "lock->trx->isolation_level > 1 || !lock_rec_get_nth_bit(lock, 1U)", file=0x564a259c02e0 "/data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc", line=4257, function=0x564a259c52c0 "void lock_release_on_prepare(trx_t*)") at assert.c:101

# 2022-08-29T15:39:56 [1054959] | #4  0x0000564a24633a48 in lock_release_on_prepare (trx=0x3c774a8544f8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc:4257

# 2022-08-29T15:39:56 [1054959] | #5  0x0000564a249b00b9 in trx_prepare (trx=0x3c774a8544f8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/trx/trx0trx.cc:1988

# 2022-08-29T15:39:56 [1054959] | #6  0x0000564a249b019e in trx_prepare_for_mysql (trx=0x3c774a8544f8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/trx/trx0trx.cc:2001

# 2022-08-29T15:39:56 [1054959] | #7  0x0000564a244d42b1 in innobase_xa_prepare (hton=0x615000002b18, thd=0x62b000150218, prepare_trx=true) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/handler/ha_innodb.cc:17003

# 2022-08-29T15:39:56 [1054959] | #8  0x0000564a23b70162 in prepare_or_error (ht=0x615000002b18, thd=0x62b000150218, all=true) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/handler.cc:1381

# 2022-08-29T15:39:56 [1054959] | #9  0x0000564a23b70387 in ha_prepare (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/handler.cc:1419

# 2022-08-29T15:39:56 [1054959] | #10 0x0000564a239dec23 in trans_xa_prepare (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/xa.cc:532

# 2022-08-29T15:39:56 [1054959] | #11 0x0000564a233f93ea in mysql_execute_command (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:5911

# 2022-08-29T15:39:56 [1054959] | #12 0x0000564a2340674a in mysql_parse (thd=0x62b000150218, rawbuf=0x62b000157238 "XA PREPARE 'xid65'  /* E_R Thread2 QNO 1411 CON_ID 70 */", length=56, parser_state=0x137e2d34abb0, is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:8101

# 2022-08-29T15:39:56 [1054959] | #13 0x0000564a233de835 in dispatch_command (command=COM_QUERY, thd=0x62b000150218, packet=0x629000cda219 "XA PREPARE 'xid65'  /* E_R Thread2 QNO 1411 CON_ID 70 */ ", packet_length=57, is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:1891

# 2022-08-29T15:39:56 [1054959] | #14 0x0000564a233db93d in do_command (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:1375

# 2022-08-29T15:39:56 [1054959] | #15 0x0000564a237c5fc7 in do_handle_one_connection (connect=0x6080000030b8, put_in_cache=true) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_connect.cc:1418

# 2022-08-29T15:39:56 [1054959] | #16 0x0000564a237c57e0 in handle_one_connection (arg=0x6080000035b8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_connect.cc:1312

# 2022-08-29T15:39:56 [1054959] | #17 0x0000564a277b8609 in start_thread (arg=<optimized out>) at pthread_create.c:477

# 2022-08-29T15:39:56 [1054959] | #18 0x000073d1298e8293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

There are also several test fails (no use of rr) where InnoDB reports

[ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 300 seconds. We intentionally crash the server because it appears to be hung.

Matthias Leich added a comment - 2022-08-29 17:43 - edited Preliminary result of RQG testing on origin/bb-10.5-MDEV-28709-sup_X_lock d2b334aaa7656e7fa41868536ae3c65df94db470 2022-08-29T18:17:04+03:00 # 2022-08-29T15:39:56 [1054959] | [rr 1057634 252092]mysqld: /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc:4257: void lock_release_on_prepare(trx_t*): Assertion `lock->trx->isolation_level > 1 || !lock_rec_get_nth_bit(lock, 1U)' failed. pluto:/data/results/1661787227/TBR-1590$ _RR_TRACE_DIR=./1/rr/ rr replay # 2022-08-29T15:39:56 [1054959] | Thread 3 (Thread 1057634.1061052): # 2022-08-29T15:39:56 [1054959] | #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 # 2022-08-29T15:39:56 [1054959] | #1 0x000073d1297eb859 in __GI_abort () at abort.c:79 # 2022-08-29T15:39:56 [1054959] | #2 0x000073d1297eb729 in __assert_fail_base (fmt=0x73d129981588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564a259c53a0 "lock->trx->isolation_level > 1 || !lock_rec_get_nth_bit(lock, 1U)", file=0x564a259c02e0 "/data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc", line=4257, function=<optimized out>) at assert.c:92 # 2022-08-29T15:39:56 [1054959] | #3 0x000073d1297fcf36 in __GI___assert_fail (assertion=0x564a259c53a0 "lock->trx->isolation_level > 1 || !lock_rec_get_nth_bit(lock, 1U)", file=0x564a259c02e0 "/data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc", line=4257, function=0x564a259c52c0 "void lock_release_on_prepare(trx_t*)") at assert.c:101 # 2022-08-29T15:39:56 [1054959] | #4 0x0000564a24633a48 in lock_release_on_prepare (trx=0x3c774a8544f8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/lock/lock0lock.cc:4257 # 2022-08-29T15:39:56 [1054959] | #5 0x0000564a249b00b9 in trx_prepare (trx=0x3c774a8544f8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/trx/trx0trx.cc:1988 # 2022-08-29T15:39:56 [1054959] | #6 0x0000564a249b019e in trx_prepare_for_mysql (trx=0x3c774a8544f8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/trx/trx0trx.cc:2001 # 2022-08-29T15:39:56 [1054959] | #7 0x0000564a244d42b1 in innobase_xa_prepare (hton=0x615000002b18, thd=0x62b000150218, prepare_trx=true) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/storage/innobase/handler/ha_innodb.cc:17003 # 2022-08-29T15:39:56 [1054959] | #8 0x0000564a23b70162 in prepare_or_error (ht=0x615000002b18, thd=0x62b000150218, all=true) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/handler.cc:1381 # 2022-08-29T15:39:56 [1054959] | #9 0x0000564a23b70387 in ha_prepare (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/handler.cc:1419 # 2022-08-29T15:39:56 [1054959] | #10 0x0000564a239dec23 in trans_xa_prepare (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/xa.cc:532 # 2022-08-29T15:39:56 [1054959] | #11 0x0000564a233f93ea in mysql_execute_command (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:5911 # 2022-08-29T15:39:56 [1054959] | #12 0x0000564a2340674a in mysql_parse (thd=0x62b000150218, rawbuf=0x62b000157238 "XA PREPARE 'xid65' /* E_R Thread2 QNO 1411 CON_ID 70 */", length=56, parser_state=0x137e2d34abb0, is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:8101 # 2022-08-29T15:39:56 [1054959] | #13 0x0000564a233de835 in dispatch_command (command=COM_QUERY, thd=0x62b000150218, packet=0x629000cda219 "XA PREPARE 'xid65' /* E_R Thread2 QNO 1411 CON_ID 70 */ ", packet_length=57, is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:1891 # 2022-08-29T15:39:56 [1054959] | #14 0x0000564a233db93d in do_command (thd=0x62b000150218) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_parse.cc:1375 # 2022-08-29T15:39:56 [1054959] | #15 0x0000564a237c5fc7 in do_handle_one_connection (connect=0x6080000030b8, put_in_cache=true) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_connect.cc:1418 # 2022-08-29T15:39:56 [1054959] | #16 0x0000564a237c57e0 in handle_one_connection (arg=0x6080000035b8) at /data/Server/bb-10.5-MDEV-28709-sup_X_lock/sql/sql_connect.cc:1312 # 2022-08-29T15:39:56 [1054959] | #17 0x0000564a277b8609 in start_thread (arg=<optimized out>) at pthread_create.c:477 # 2022-08-29T15:39:56 [1054959] | #18 0x000073d1298e8293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 There are also several test fails (no use of rr) where InnoDB reports [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 300 seconds. We intentionally crash the server because it appears to be hung.

Matthias Leich added a comment - 2022-09-02 10:14

origin/bb-10.6-~~MDEV-28709~~-sup_X_lock 5acabbf1c2cc5c3880ef152bed36922d23cfba45 2022-08-31T15:04:56+03:00
performed well in RQG testing. No new bad effects. The replayed one are in the main trees too.
Please be aware that my RQG tests are unable to reveal the bad effect ~~MDEV-28709~~ is about.

Matthias Leich added a comment - 2022-09-02 10:14 origin/bb-10.6- MDEV-28709 -sup_X_lock 5acabbf1c2cc5c3880ef152bed36922d23cfba45 2022-08-31T15:04:56+03:00 performed well in RQG testing. No new bad effects. The replayed one are in the main trees too. Please be aware that my RQG tests are unable to reveal the bad effect MDEV-28709 is about.

Matthias Leich added a comment - 2022-09-07 12:33

origin/bb-10.5-~~MDEV-28709~~-sup_X_lock-debug 45238f905bbaa5c5186129bfafe072814f283371 2022-09-05T20:07:41+03:00
performed well in RQG testing.

Matthias Leich added a comment - 2022-09-07 12:33 origin/bb-10.5- MDEV-28709 -sup_X_lock-debug 45238f905bbaa5c5186129bfafe072814f283371 2022-09-05T20:07:41+03:00 performed well in RQG testing.

Vladislav Lesin added a comment - 2022-10-14 12:10

I have added one more fix which forbids any gap lock inheritance after XA is prepared.

Vladislav Lesin added a comment - 2022-10-14 12:10 I have added one more fix which forbids any gap lock inheritance after XA is prepared.

MariaDB Server

unexpected X lock on Supremum in READ COMMITTED

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration