布景
业务端遇到报错为"Deadlock found when trying to get lock; try restarting transaction"
则标明有死锁产生
称号 | 装备 |
---|---|
数据库版别 | GreatSQL 8.0.26 |
阻隔等级 | Read-Commited |
innodb status 日志
greatsql> show engine innodb statusG
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2024-01-28 16:55:38 140737023727360 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 14 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 41 srv_active, 0 srv_shutdown, 17830 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
-------------
RW-LATCH INFO
-------------
Total number of rw-locks 132361
OS WAIT ARRAY INFO: reservation count 11180
OS WAIT ARRAY INFO: signal count 11177
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-01-28 16:53:40 140735053358848
*** (1) TRANSACTION:
TRANSACTION 37616, ACTIVE 8 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1192, 1 row lock(s), undo log entries 1
MySQL thread id 16, OS thread handle 140737023432448, query id 652 127.0.0.1 root update
insert into info values (50,11)
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 26 page no 5 n bits 80 index uk_name of table `apple`.`info` trx id 37616 lock mode S waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000b; asc ;;
1: len 4; hex 80000028; asc (;;
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 26 page no 5 n bits 80 index uk_name of table `apple`.`info` trx id 37616 lock mode S waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000b; asc ;;
1: len 4; hex 80000028; asc (;;
*** (2) TRANSACTION:
TRANSACTION 37615, ACTIVE 24 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1192, 2 row lock(s), undo log entries 2
MySQL thread id 15, OS thread handle 140737024022272, query id 653 127.0.0.1 root update
insert into info values (60,8)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 26 page no 5 n bits 80 index uk_name of table `apple`.`info` trx id 37615 lock_mode X locks rec but not gap
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000b; asc ;;
1: len 4; hex 80000028; asc (;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 26 page no 5 n bits 80 index uk_name of table `apple`.`info` trx id 37615 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000b; asc ;;
1: len 4; hex 80000028; asc (;;
*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
查看表结构
greatsql> show create table info G
*************************** 1. row ***************************
Table: info
Create Table: CREATE TABLE `info` (
`id` int NOT NULL AUTO_INCREMENT,
`name` int NOT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `uk_name` (`name`)
) ENGINE=InnoDB AUTO_INCREMENT=61 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.01 sec)
梳理 innodb status 日志
- 收拾如下:
业务 | T1 | T2 |
---|---|---|
操作 | insert into info values (50,11) | insert into info values (60,8) |
关联的对象 | 表apple.info的仅有索引 uk_name | 表apple.info的仅有索引 uk_name |
持有的锁 | lock mode S waitingheap no 7 11,40(十六进制为8,28) | lock_mode X locks rec but not gapheap no 7 11,40(十六进制为8,28) |
等候的锁 | lock mode S waitingheap no 7 11,40(十六进制为8,28) | lock_mode X locks gap before rec insert intention waitingheap no 7 11,40(十六进制为8,28) |
-
首要业务T2获取到了uk_name中记载11的 lock x,rec not not gap 锁
-
业务T1尝试获取uk_name中记载11的lock s, next key lock,因为T2持有了记载的独占锁,因而被T1阻塞
-
业务T2尝试获取uk_name中记载11的lock x, gap before rec,insert intention,但被阻塞
获取业务前史SQL句子
经过体系表方法
经过performance_schema.threads、performance_schema.events_statements_history、performance_schema.events_statements_history_long等体系表获取前史SQL
- 依据GreatSQL thread id取得线程id
greatsql> select PROCESSLIST_ID,THREAD_ID,THREAD_OS_ID from performance_schema.threads where processlist_id in (15,16);
---------------- ----------- --------------
| PROCESSLIST_ID | THREAD_ID | THREAD_OS_ID |
---------------- ----------- --------------
| 15 | 61 | 5714 |
| 16 | 62 | 5719 |
---------------- ----------- --------------
2 rows in set (0.00 sec)
- 依据线程id取得线程前史SQL
greatsql> select THREAD_ID,EVENT_ID,CURRENT_SCHEMA,SQL_TEXT,MESSAGE_TEXT,EVENT_NAME,SOURCE from performance_schema.events_statements_history where thread_id in (61,62) order by THREAD_ID,EVENT_ID;
----------- ---------- ---------------- --------------------------------- -------------------------------------------------------------------- -------------------------- ---------------------------------
| THREAD_ID | EVENT_ID | CURRENT_SCHEMA | SQL_TEXT | MESSAGE_TEXT | EVENT_NAME | SOURCE |
----------- ---------- ---------------- --------------------------------- -------------------------------------------------------------------- -------------------------- ---------------------------------
| 61 | 3762 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 3807 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 3852 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 3897 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 3942 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 3987 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 4032 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 61 | 4077 | apple | begin | NULL | statement/sql/begin | init_net_server_extension.cc:94 |
| 61 | 4100 | apple | insert into info values (40,11) | NULL | statement/sql/insert | init_net_server_extension.cc:94 |
| 61 | 4569 | apple | insert into info values (60,8) | NULL | statement/sql/insert | init_net_server_extension.cc:94 |
| 62 | 3215 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3260 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3305 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3350 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3395 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3440 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3485 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3530 | apple | NULL | NULL | statement/com/Field List | init_net_server_extension.cc:94 |
| 62 | 3575 | apple | begin | NULL | statement/sql/begin | init_net_server_extension.cc:94 |
| 62 | 3598 | apple | insert into info values (50,11) | Deadlock found when trying to get lock; try restarting transaction | statement/sql/insert | init_net_server_extension.cc:94 |
----------- ---------- ---------------- --------------------------------- -------------------------------------------------------------------- -------------------------- ---------------------------------
20 rows in set (0.00 sec)
-
观察
show engine innodb status
中的GreatSQL thread id 16和GreatSQL thread id 15 -
经过
performance_schema.threads
获取THREAD_ID -
经过
performance_schema.events_statements_history
获取THREAD_ID履行的前史SQL以及履行时间
终究可复现出如下业务SQL:
业务 | T1 | T2 |
---|---|---|
句子 | begin; | begin; |
句子 | insert into info values (40,11); | |
句子 | insert into info values (50,11); | |
句子 | insert into info values (60,8); |
经过解析binlog
$ mysqlbinlog -vv –base64-output=decode-rows bin.000030
SET @@SESSION.GTID_NEXT= 'e319a624-b2ce-11ee-9aac-00163e62ca8a:8696'/*!*/;
# at 10314
#240128 16:52:35 server id 1024 end_log_pos 10390 CRC32 0x59edb313 Query thread_id=18 exec_time=0 error_code=0
SET TIMESTAMP=1706431955/*!*/;
BEGIN
/*!*/;
# at 10390
#240128 16:52:35 server id 1024 end_log_pos 10442 CRC32 0xc03dea61 Table_map: `apple`.`info` mapped to number 370
# at 10442
#240128 16:52:35 server id 1024 end_log_pos 10486 CRC32 0x670e0c66 Write_rows: table id 370 flags: STMT_END_F
### INSERT INTO `apple`.`info`
### SET
### @1=30 /* INT meta=0 nullable=0 is_null=0 */
### @2=30 /* INT meta=0 nullable=0 is_null=0 */
# at 10486
#240128 16:52:35 server id 1024 end_log_pos 10517 CRC32 0xab4e0d89 Xid = 598
COMMIT/*!*/;
# at 10517
#240128 19:22:12 server id 1024 end_log_pos 10596 CRC32 0x4f4cf08e GTID last_committed=30 sequence_number=36 rbr_only=yes original_committed_timestamp=1706440932450590 immediate_commit_timestamp=1706440932450590 transaction_length=378
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1706440932450590 (2024-01-28 19:22:12.450590 CST)
# immediate_commit_timestamp=1706440932450590 (2024-01-28 19:22:12.450590 CST)
/*!80001 SET @@session.original_commit_timestamp=1706440932450590*//*!*/;
/*!80014 SET @@session.original_server_version=80026*//*!*/;
/*!80014 SET @@session.immediate_server_version=80026*//*!*/;
SET @@SESSION.GTID_NEXT= 'e319a624-b2ce-11ee-9aac-00163e62ca8a:8697'/*!*/;
# at 10596
#240128 16:53:16 server id 1024 end_log_pos 10672 CRC32 0xf222c003 Query thread_id=15 exec_time=0 error_code=0
SET TIMESTAMP=1706431996/*!*/;
BEGIN
/*!*/;
# at 10672
#240128 16:53:16 server id 1024 end_log_pos 10724 CRC32 0x20cb8c86 Table_map: `apple`.`info` mapped to number 370
# at 10724
#240128 16:53:16 server id 1024 end_log_pos 10768 CRC32 0xd8f53958 Write_rows: table id 370 flags: STMT_END_F
### INSERT INTO `apple`.`info`
### SET
### @1=40 /* INT meta=0 nullable=0 is_null=0 */
### @2=11 /* INT meta=0 nullable=0 is_null=0 */
# at 10768
#240128 16:53:40 server id 1024 end_log_pos 10820 CRC32 0x23f22580 Table_map: `apple`.`info` mapped to number 370
# at 10820
#240128 16:53:40 server id 1024 end_log_pos 10864 CRC32 0x182ecdef Write_rows: table id 370 flags: STMT_END_F
### INSERT INTO `apple`.`info`
### SET
### @1=60 /* INT meta=0 nullable=0 is_null=0 */
### @2=8 /* INT meta=0 nullable=0 is_null=0 */
# at 10864
#240128 19:22:12 server id 1024 end_log_pos 10895 CRC32 0x57fd1d3c Xid = 650
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
依据binlog中部分SET @@SESSION.GTID_NEXT= 'e319a624-b2ce-11ee-9aac-00163e62ca8a:8697'
该GTID的业务信息,可恢复T2,但T1履行的句子因为被回滚了,则不会记载到binlog,可敞开general log日志获取排查
业务 | T1 | T2 |
---|---|---|
句子 | begin; | begin; |
句子 | insert into info values (40,11); | |
句子 | insert into info values (50,11); | |
句子 | insert into info values (60,8); |
剖析死锁
-
T1、T2敞开了一个业务
-
随后T2履行了刺进(40,11)的insert句子:
insert into info values (40,11)
-
T1履行了刺进(50,11)的insert句子:
insert into info values (50,11)
进行仅有性抵触查看,尝试获取LOCK_S -
然后T1地点的衔接会将T2中的隐式锁转换为显示锁,此刻T2将获取Lock X, Rec_not_gap。因为T2的Lock X, Rec_not_gap与T1的LOCK S不兼容,因而T1被阻塞
-
随后,T2又履行了(60,8)的insert句子:
insert into info values (60,8)
因为其刺进的仅有索引值是8,因而不存在主键抵触,直接履行乐观刺进操作。履行乐观刺进时,需要查看其它业务是否阻塞insert操作。其核心是获取待刺进记载的下一个值(这儿刚好是10),并获取该记载上的所有锁,与需要添加的锁判别是否存在抵触。 -
T1持有了记载11的LOCK_S锁与T2的LOCK_X、LOCK_INSERT_INTENTION不兼容,因而T2被T1阻塞
-
死锁构成。
处理
• 恰当的减少Unique索引
• 避免刺进重复的值(仅有索引地点列)
Enjoy GreatSQL :)
关于 GreatSQL
GreatSQL是适用于金融级应用的国内自主开源数据库,具有高性能、高牢靠、高易用性、高安全等多个核心特性,可以作为MySQL或Percona Server的可选替换,用于线上生产环境,且完全免费并兼容MySQL或Percona Server。
相关链接: GreatSQL社区 Gitee GitHub Bilibili
GreatSQL社区:
社区有奖主张反馈: greatsql.cn/thread-54-1…
社区博客有奖征稿概况: greatsql.cn/thread-100-…
(对文章有疑问或者有独到见解都可以去社区官网提出或分享哦~)
技术交流群:
微信&QQ群:
QQ群:533341697
微信群:添加GreatSQL社区助手(微信号:wanlidbc
)老友,待社区助手拉您进群。