发帖
翼度科技»论坛 › 编程开发 › mysql › 查看内容

故障解析丨一次死锁问题的解决

库芬王的爸爸

5

主题

5

帖子

15

积分

新手上路

Rank: 1

积分
15
显示全部楼层
背景

业务端遇到报错为"Deadlock found when trying to get lock; try restarting transaction"则表明有死锁发生
名称配置数据库版本GreatSQL 8.0.26隔离级别Read-Commitedinnodb status 日志
  1. greatsql> show engine innodb status\G
  2. *************************** 1. row ***************************
  3.   Type: InnoDB
  4.   Name:
  5. Status:
  6. =====================================
  7. 2024-01-28 16:55:38 140737023727360 INNODB MONITOR OUTPUT
  8. =====================================
  9. Per second averages calculated from the last 14 seconds
  10. -----------------
  11. BACKGROUND THREAD
  12. -----------------
  13. srv_master_thread loops: 41 srv_active, 0 srv_shutdown, 17830 srv_idle
  14. srv_master_thread log flush and writes: 0
  15. ----------
  16. SEMAPHORES
  17. ----------
  18. -------------
  19. RW-LATCH INFO
  20. -------------
  21. Total number of rw-locks 132361
  22. OS WAIT ARRAY INFO: reservation count 11180
  23. OS WAIT ARRAY INFO: signal count 11177
  24. RW-shared spins 0, rounds 0, OS waits 0
  25. RW-excl spins 0, rounds 0, OS waits 0
  26. RW-sx spins 0, rounds 0, OS waits 0
  27. Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
  28. ------------------------
  29. LATEST DETECTED DEADLOCK
  30. ------------------------
  31. 2024-01-28 16:53:40 140735053358848
  32. *** (1) TRANSACTION:
  33. TRANSACTION 37616, ACTIVE 8 sec inserting
  34. mysql tables in use 1, locked 1
  35. LOCK WAIT 2 lock struct(s), heap size 1192, 1 row lock(s), undo log entries 1
  36. MySQL thread id 16, OS thread handle 140737023432448, query id 652 127.0.0.1 root update
  37. insert into info values (50,11)
  39. *** (1) HOLDS THE LOCK(S):
  40. 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
  41. Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
  42. 0: len 4; hex 8000000b; asc     ;;
  43. 1: len 4; hex 80000028; asc    (;;
  46. *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
  47. 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
  48. Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
  49. 0: len 4; hex 8000000b; asc     ;;
  50. 1: len 4; hex 80000028; asc    (;;
  53. *** (2) TRANSACTION:
  54. TRANSACTION 37615, ACTIVE 24 sec inserting
  55. mysql tables in use 1, locked 1
  56. LOCK WAIT 3 lock struct(s), heap size 1192, 2 row lock(s), undo log entries 2
  57. MySQL thread id 15, OS thread handle 140737024022272, query id 653 127.0.0.1 root update
  58. insert into info values (60,8)
  60. *** (2) HOLDS THE LOCK(S):
  61. 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
  62. Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
  63. 0: len 4; hex 8000000b; asc     ;;
  64. 1: len 4; hex 80000028; asc    (;;
  67. *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
  68. 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
  69. Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
  70. 0: len 4; hex 8000000b; asc     ;;
  71. 1: len 4; hex 80000028; asc    (;;
  73. *** WE ROLL BACK TRANSACTION (1)
  74. ------------
  75. TRANSACTIONS
  76. ------------
复制代码
查看表结构
  1. greatsql> show create table info \G
  2. *************************** 1. row ***************************
  3.        Table: info
  4. Create Table: CREATE TABLE `info` (
  5.   `id` int NOT NULL AUTO_INCREMENT,
  6.   `name` int NOT NULL,
  7.   PRIMARY KEY (`id`),
  8.   UNIQUE KEY `uk_name` (`name`)
  9. ) ENGINE=InnoDB AUTO_INCREMENT=61 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
  10. 1 row in set (0.01 sec)
复制代码
梳理 innodb status 日志


  • 整理如下：
事务T1T2操作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
  1. greatsql> select PROCESSLIST_ID,THREAD_ID,THREAD_OS_ID from  performance_schema.threads where processlist_id in (15,16);
  2. +----------------+-----------+--------------+
  3. | PROCESSLIST_ID | THREAD_ID | THREAD_OS_ID |
  4. +----------------+-----------+--------------+
  5. |             15 |        61 |         5714 |
  6. |             16 |        62 |         5719 |
  7. +----------------+-----------+--------------+
  8. 2 rows in set (0.00 sec)
复制代码

  • 根据线程id获得线程历史SQL
  1. 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;
  2. +-----------+----------+----------------+---------------------------------+--------------------------------------------------------------------+--------------------------+---------------------------------+
  3. | THREAD_ID | EVENT_ID | CURRENT_SCHEMA | SQL_TEXT                        | MESSAGE_TEXT                                                       | EVENT_NAME               | SOURCE                          |
  4. +-----------+----------+----------------+---------------------------------+--------------------------------------------------------------------+--------------------------+---------------------------------+
  5. |        61 |     3762 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  6. |        61 |     3807 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  7. |        61 |     3852 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  8. |        61 |     3897 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  9. |        61 |     3942 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  10. |        61 |     3987 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  11. |        61 |     4032 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  12. |        61 |     4077 | apple          | begin                           | NULL                                                               | statement/sql/begin      | init_net_server_extension.cc:94 |
  13. |        61 |     4100 | apple          | insert into info values (40,11) | NULL                                                               | statement/sql/insert     | init_net_server_extension.cc:94 |
  14. |        61 |     4569 | apple          | insert into info values (60,8)  | NULL                                                               | statement/sql/insert     | init_net_server_extension.cc:94 |
  15. |        62 |     3215 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  16. |        62 |     3260 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  17. |        62 |     3305 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  18. |        62 |     3350 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  19. |        62 |     3395 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  20. |        62 |     3440 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  21. |        62 |     3485 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  22. |        62 |     3530 | apple          | NULL                            | NULL                                                               | statement/com/Field List | init_net_server_extension.cc:94 |
  23. |        62 |     3575 | apple          | begin                           | NULL                                                               | statement/sql/begin      | init_net_server_extension.cc:94 |
  24. |        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 |
  25. +-----------+----------+----------------+---------------------------------+--------------------------------------------------------------------+--------------------------+---------------------------------+
  26. 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：
事务T1T2语句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
  1. SET @@SESSION.GTID_NEXT= 'e319a624-b2ce-11ee-9aac-00163e62ca8a:8696'/*!*/;
  2. # at 10314
  3. #240128 16:52:35 server id 1024  end_log_pos 10390 CRC32 0x59edb313         Query        thread_id=18        exec_time=0        error_code=0
  4. SET TIMESTAMP=1706431955/*!*/;
  5. BEGIN
  6. /*!*/;
  7. # at 10390
  8. #240128 16:52:35 server id 1024  end_log_pos 10442 CRC32 0xc03dea61         Table_map: `apple`.`info` mapped to number 370
  9. # at 10442
  10. #240128 16:52:35 server id 1024  end_log_pos 10486 CRC32 0x670e0c66         Write_rows: table id 370 flags: STMT_END_F
  11. ### INSERT INTO `apple`.`info`
  12. ### SET
  13. ###   @1=30 /* INT meta=0 nullable=0 is_null=0 */
  14. ###   @2=30 /* INT meta=0 nullable=0 is_null=0 */
  15. # at 10486
  16. #240128 16:52:35 server id 1024  end_log_pos 10517 CRC32 0xab4e0d89         Xid = 598
  17. COMMIT/*!*/;
  18. # at 10517
  19. #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
  20. /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
  21. # original_commit_timestamp=1706440932450590 (2024-01-28 19:22:12.450590 CST)
  22. # immediate_commit_timestamp=1706440932450590 (2024-01-28 19:22:12.450590 CST)
  23. /*!80001 SET @@session.original_commit_timestamp=1706440932450590*//*!*/;
  24. /*!80014 SET @@session.original_server_version=80026*//*!*/;
  25. /*!80014 SET @@session.immediate_server_version=80026*//*!*/;
  26. SET @@SESSION.GTID_NEXT= 'e319a624-b2ce-11ee-9aac-00163e62ca8a:8697'/*!*/;
  27. # at 10596
  28. #240128 16:53:16 server id 1024  end_log_pos 10672 CRC32 0xf222c003         Query        thread_id=15        exec_time=0        error_code=0
  29. SET TIMESTAMP=1706431996/*!*/;
  30. BEGIN
  31. /*!*/;
  32. # at 10672
  33. #240128 16:53:16 server id 1024  end_log_pos 10724 CRC32 0x20cb8c86         Table_map: `apple`.`info` mapped to number 370
  34. # at 10724
  35. #240128 16:53:16 server id 1024  end_log_pos 10768 CRC32 0xd8f53958         Write_rows: table id 370 flags: STMT_END_F
  36. ### INSERT INTO `apple`.`info`
  37. ### SET
  38. ###   @1=40 /* INT meta=0 nullable=0 is_null=0 */
  39. ###   @2=11 /* INT meta=0 nullable=0 is_null=0 */
  40. # at 10768
  41. #240128 16:53:40 server id 1024  end_log_pos 10820 CRC32 0x23f22580         Table_map: `apple`.`info` mapped to number 370
  42. # at 10820
  43. #240128 16:53:40 server id 1024  end_log_pos 10864 CRC32 0x182ecdef         Write_rows: table id 370 flags: STMT_END_F
  44. ### INSERT INTO `apple`.`info`
  45. ### SET
  46. ###   @1=60 /* INT meta=0 nullable=0 is_null=0 */
  47. ###   @2=8 /* INT meta=0 nullable=0 is_null=0 */
  48. # at 10864
  49. #240128 19:22:12 server id 1024  end_log_pos 10895 CRC32 0x57fd1d3c         Xid = 650
  50. COMMIT/*!*/;
  51. SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
  52. DELIMITER ;
  53. # End of log file
  54. /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
  55. /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
复制代码
根据binlog中部分SET @@SESSION.GTID_NEXT= 'e319a624-b2ce-11ee-9aac-00163e62ca8a:8697'该GTID的事务信息，可恢复T2，但T1执行的语句由于被回滚了，则不会记录到binlog，可开启general log日志获取排查
事务T1T2语句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
来源:https://www.cnblogs.com/greatsql/p/18079727
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！

上一篇: 故障解析丨一次死锁问题的解决

下一篇: innodb_log_file_size 和 innodb_buffer_pool_size

发表于 2024-3-18 15:19:14

举报 回复 使用道具

返回列表 发新帖

Archiver|手机版|小黑屋|翼度科技

Copyright © 2001-2020, Tencent Cloud.　Powered by Discuz! X3.4