Bug #102098 XA Transactions Next-key Lock lost lead to slave replication lock wait timeout
Submitted: 31 Dec 2020 9:40 Modified: 2 Mar 2021 10:51
Reporter: lei yue Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: XA transactions Severity:S2 (Serious)
Version:8.0.22,5.7.32 OS:CentOS (7.4)
Assigned to: MySQL Verification Team CPU Architecture:x86

[31 Dec 2020 9:40] lei yue
Description:
1. a table has a unique index(idx_ticketid_attrid) and four records

2. do xa prepare trx1, delete record primary key a

3. If we then update a record a(with idx_ticketid_attrid value b). this update will blocked. (trx2)

4. If we restart mysqld, we will find that the xa transaction exists, but the lock information is lost

5. If we update which row again, we find that it can be executed normally

6. Check the slave and find that it will always be in a lock waiting state, and you need to restart slave mysqld to solve it

How to repeat:
0. MySQL operating environment
mysql> show variables like 'tran%iso%';
+-----------------------+----------------+
| Variable_name         | Value          |
+-----------------------+----------------+
| transaction_isolation | READ-COMMITTED |
+-----------------------+----------------+
1 row in set (0.00 sec)

mysql> \s
--------------
mysql  Ver 8.0.22 for Linux on x86_64 (MySQL Community Server - GPL)

Connection id:          11
Current database:
Current user:           root@localhost
SSL:                    Not in use
Current pager:          stdout
Using outfile:          ''
Using delimiter:        ;
Server version:         8.0.22 MySQL Community Server - GPL
Protocol version:       10
Connection:             Localhost via UNIX socket
Server characterset:    utf8mb4
Db     characterset:    utf8mb4
Client characterset:    utf8mb4
Conn.  characterset:    utf8mb4
UNIX socket:            /var/lib/mysql/sock/mysql.sock
Binary data as:         Hexadecimal
Uptime:                 30 sec

Threads: 1  Questions: 26  Slow queries: 0  Opens: 147  Flush tables: 3  Open tables: 65  Queries per second avg: 0.866
--------------

1. create a table and insert 4 records
CREATE TABLE `mytable` (
  `Id` bigint(20) NOT NULL,
  `TicketId` bigint(20) DEFAULT '0',
  `AttrId` bigint(20) DEFAULT '0',
  `AttrValueId` bigint(20) DEFAULT '0',
  `Position` int(10) DEFAULT '0',
  `db_create_time` timestamp NOT NULL DEFAULT '2000-01-01 00:00:00',
  `db_update_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`Id`),
  UNIQUE KEY `idx_ticketid_attrid` (`TicketId`,`AttrId`),
  KEY `idx_ticketid_pos` (`TicketId`,`Position`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

insert into `mytable` values (506612135,90372038,1,506610230,1,'2019-03-27 19:02:19','2019-03-27 19:02:19');
insert into `mytable` values (506612498,90374047,2,506612498,1,'2019-03-27 19:04:50','2019-03-27 19:04:50');
insert into `mytable` values (506623656,90375007,1,506623656,0,'2019-03-27 19:08:15','2019-03-27 19:08:15');
insert into `mytable` values (506624532,90378234,3,506635312,1,'2019-03-27 19:10:23','2019-03-27 19:10:23');

2. session1 start XA Transactions one
mysql> xa start '1';update mytable set Id=506698389 where id=506612498;
Query OK, 0 rows affected (0.00 sec)

Query OK, 1 row affected (0.00 sec)

mysql> xa end '1';xa prepare '1';
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.01 sec)

3. session2 start XA Transactions two, now update may be blocked
mysql> xa start '2';
Query OK, 0 rows affected (0.01 sec)

mysql> update mytable set TicketId=90375008 where TicketId=90375007; //waiting

4. session3 Query lock information
mysql> select ENGINE,ENGINE_TRANSACTION_ID,THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks;
+--------+-----------------------+-----------+---------------+-------------+---------------------+-----------+---------------+-------------+------------------------+
| ENGINE | ENGINE_TRANSACTION_ID | THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME          | LOCK_TYPE | LOCK_MODE     | LOCK_STATUS | LOCK_DATA              |
+--------+-----------------------+-----------+---------------+-------------+---------------------+-----------+---------------+-------------+------------------------+
| INNODB |                  1592 |        70 | test          | mytable     | NULL                | TABLE     | IX            | GRANTED     | NULL                   |
| INNODB |                  1592 |        70 | test          | mytable     | idx_ticketid_attrid | RECORD    | X,REC_NOT_GAP | WAITING     | 90375007, 1, 506623656 |
| INNODB |                  1590 |        69 | test          | mytable     | NULL                | TABLE     | IX            | GRANTED     | NULL                   |
| INNODB |                  1590 |        69 | test          | mytable     | PRIMARY             | RECORD    | X,REC_NOT_GAP | GRANTED     | 506612498              |
| INNODB |                  1590 |        69 | test          | mytable     | idx_ticketid_attrid | RECORD    | X,REC_NOT_GAP | GRANTED     | 90374047, 2, 506612498 |
| INNODB |                  1590 |        69 | test          | mytable     | idx_ticketid_attrid | RECORD    | S,REC_NOT_GAP | GRANTED     | 90375007, 1, 506623656 |
+--------+-----------------------+-----------+---------------+-------------+---------------------+-----------+---------------+-------------+------------------------+
6 rows in set (0.00 sec)

5. restart mysqld and Query error log
# ps -ef|grep mysqld
root       366 79955  0 17:08 pts/1    00:00:00 grep --color=auto mysqld
root     85032     1  0 17:05 pts/0    00:00:00 /bin/sh /usr/local/mysql/bin/mysqld_safe --defaults-file=/etc/mysql/my.cnf
mysql    86574 85032  1 17:05 pts/0    00:00:02 /usr/local/mysql/bin/mysqld --defaults-file=/etc/mysql/my.cnf --basedir=/usr/local/mysql --datadir=/var/lib/mysql/data --plugin-dir=/usr/local/mysql/lib/plugin --user=mysql --log-error=/var/lib/mysql/log/error.log --open-files-limit=65535 --pid-file=/var/lib/mysql/sock/mysql.pid --socket=/var/lib/mysql/sock/mysql.sock --port=3306

# kill 86574 85032 

# tail -f error.log
2020-12-31T17:09:22.420107+08:00 0 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"
2020-12-31T17:09:22.420127+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'MEMORY'
2020-12-31T17:09:22.420141+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'CSV'
2020-12-31T17:09:22.420150+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'sha2_cache_cleaner'
2020-12-31T17:09:22.420159+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'caching_sha2_password'
2020-12-31T17:09:22.420168+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'sha256_password'
2020-12-31T17:09:22.420176+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'mysql_native_password'
2020-12-31T17:09:22.420328+08:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'binlog'
2020-12-31T17:09:22.421212+08:00 0 [System] [MY-010910] [Server] /usr/local/mysql/bin/mysqld: Shutdown complete (mysqld 8.0.22)  MySQL Community Server - GPL.

# mysqld_safe --defaults-file=/etc/mysql/my.cnf &

# tail -f error.log
2020-12-31T17:10:27.474716+08:00 0 [Note] [MY-010264] [Server]   - '::' resolves to '::';
2020-12-31T17:10:27.474966+08:00 0 [Note] [MY-010251] [Server] Server socket created on IP: '::'.
2020-12-31T17:10:27.489269+08:00 0 [Note] [MY-011025] [Repl] Failed to start slave threads for channel ''.
2020-12-31T17:10:27.491482+08:00 0 [System] [MY-010931] [Server] /usr/local/mysql/bin/mysqld: ready for connections. Version: '8.0.22'  socket: '/var/lib/mysql/sock/mysql.sock'  port: 3306  MySQL Community Server - GPL.
2020-12-31T17:10:27.491497+08:00 0 [System] [MY-013292] [Server] Admin interface ready for connections, address: '127.0.0.1'  port: 33062

6. xa recover command to view XA transaction information
mysql> xa recover;
+----------+--------------+--------------+------+
| formatID | gtrid_length | bqual_length | data |
+----------+--------------+--------------+------+
|        1 |            1 |            0 | 1    |
+----------+--------------+--------------+------+
1 row in set (0.00 sec)

7. Check the lock information again, Found that the lock was lost
mysql> select ENGINE,ENGINE_TRANSACTION_ID,THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks;
+--------+-----------------------+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
| ENGINE | ENGINE_TRANSACTION_ID | THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+--------+-----------------------+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
| INNODB |                  1590 |         2 | test          | mytable     | NULL       | TABLE     | IX        | GRANTED     | NULL      |
+--------+-----------------------+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
1 row in set (0.00 sec)

8. reopen session2 start XA Transactions two, now update can be executed normally
mysql> xa start '2';
Query OK, 0 rows affected (0.00 sec)

mysql> update mytable set TicketId=90375008 where TicketId=90375007;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> xa end '2';xa commit '2';
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> xa recover;
+----------+--------------+--------------+------+
| formatID | gtrid_length | bqual_length | data |
+----------+--------------+--------------+------+
|        1 |            1 |            0 | 2    |
|        1 |            1 |            0 | 1    |
+----------+--------------+--------------+------+
2 rows in set (0.00 sec)

9. go to the slave to view lock information and error log
mysql> select * from performance_schema.data_lock_waits\G
*************************** 1. row ***************************
                          ENGINE: INNODB
       REQUESTING_ENGINE_LOCK_ID: 140503804538264:2:5:2:140503815367160
REQUESTING_ENGINE_TRANSACTION_ID: 2404
            REQUESTING_THREAD_ID: 70
             REQUESTING_EVENT_ID: 23
REQUESTING_OBJECT_INSTANCE_BEGIN: 140503815367160
         BLOCKING_ENGINE_LOCK_ID: 140503804870392:2:5:2:140500260901736
  BLOCKING_ENGINE_TRANSACTION_ID: 2380
              BLOCKING_THREAD_ID: 70
               BLOCKING_EVENT_ID: 12
  BLOCKING_OBJECT_INSTANCE_BEGIN: 140500260901736
1 row in set (0.00 sec)

mysql> select ENGINE,ENGINE_TRANSACTION_ID,THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks;
+--------+-----------------------+-----------+---------------+-------------+---------------------+-----------+---------------+-------------+------------------------+
| ENGINE | ENGINE_TRANSACTION_ID | THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME          | LOCK_TYPE | LOCK_MODE     | LOCK_STATUS | LOCK_DATA              |
+--------+-----------------------+-----------+---------------+-------------+---------------------+-----------+---------------+-------------+------------------------+
| INNODB |                  2404 |        70 | test          | mytable     | NULL                | TABLE     | IX            | GRANTED     | NULL                   |
| INNODB |                  2404 |        70 | test          | mytable     | PRIMARY             | RECORD    | X,REC_NOT_GAP | GRANTED     | 506623656              |
| INNODB |                  2404 |        70 | test          | mytable     | idx_ticketid_attrid | RECORD    | X,REC_NOT_GAP | WAITING     | 90375007, 1, 506623656 |
| INNODB |                  2380 |        70 | test          | mytable     | NULL                | TABLE     | IX            | GRANTED     | NULL                   |
| INNODB |                  2380 |        70 | test          | mytable     | PRIMARY             | RECORD    | X,REC_NOT_GAP | GRANTED     | 506612498              |
| INNODB |                  2380 |        70 | test          | mytable     | idx_ticketid_attrid | RECORD    | X,REC_NOT_GAP | GRANTED     | 90374047, 2, 506612498 |
| INNODB |                  2380 |        70 | test          | mytable     | idx_ticketid_attrid | RECORD    | S,REC_NOT_GAP | GRANTED     | 90375007, 1, 506623656 |
+--------+-----------------------+-----------+---------------+-------------+---------------------+-----------+---------------+-------------+------------------------+
7 rows in set (0.00 sec)

# tail -f error.log
2020-12-31T17:32:21.330310+08:00 12 [Warning] [MY-010584] [Repl] Slave SQL for channel '': Worker 1 failed executing transaction '596594a0-4b47-11eb-9e94-000af7d077a0:8' at master log mysql-bin.000003, end_log_pos 645; Could not execute Update_rows event on table test.mytable; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log mysql-bin.000002, end_log_pos 645, Error_code: MY-001205
2020-12-31T17:33:13.334235+08:00 12 [Warning] [MY-010584] [Repl] Slave SQL for channel '': Worker 1 failed executing transaction '596594a0-4b47-11eb-9e94-000af7d077a0:8' at master log mysql-bin.000003, end_log_pos 645; Could not execute Update_rows event on table test.mytable; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log mysql-bin.000002, end_log_pos 645, Error_code: MY-001205
2020-12-31T17:34:06.338031+08:00 12 [Warning] [MY-010584] [Repl] Slave SQL for channel '': Worker 1 failed executing transaction '596594a0-4b47-11eb-9e94-000af7d077a0:8' at master log mysql-bin.000003, end_log_pos 645; Could not execute Update_rows event on table test.mytable; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log mysql-bin.000002, end_log_pos 645, Error_code: MY-001205
2020-12-31T17:35:00.341760+08:00 12 [Warning] [MY-010584] [Repl] Slave SQL for channel '': Worker 1 failed executing transaction '596594a0-4b47-11eb-9e94-000af7d077a0:8' at master log mysql-bin.000003, end_log_pos 645; Could not execute Update_rows event on table test.mytable; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log mysql-bin.000002, end_log_pos 645, Error_code: MY-001205

10. at this time, you need to restart slave mysqld to solve
[2 Feb 2021 10:51] MySQL Verification Team
Hi,

If you look at:
https://dev.mysql.com/doc/refman/8.0/en/xa-restrictions.html

You see that XA transactions are not yet safe when an unclean shutdown happens. 

Can you reproduce this with a proper mysqld shutdown ? (I tried and could not with 8.0.23)

all best
Bogdan
[3 Mar 2021 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".