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