MySQL DeadLock故障排查全过程记录

【作者】

刘博:携程技术保障中心数据库高级经理,主要关注Sql server和Mysql的运维和故障处理。

【环境】

版本号:5.6.21

隔离级别:REPEATABLE READ

【问题描述】

接到监控报警,有一个线上的应用DeadLock报错,每15分钟会准时出现,报错统计如下图:

登录Mysql服务器查看日志:

mysql> show engine innodb status\G

*** (1) TRANSACTION:

TRANSACTION 102973, ACTIVE 11 sec starting index read

mysql tables in use 3, locked 3

LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s)

MySQL thread id 6, OS thread handle 140024996574976, query id 83 localhost us updating

UPDATE TestTable

SET column1 = 1,

Column2 = sysdate(),

Column3= '026'

Column4 = 0

AND column5 = 485

AND column6 = 'SEK'

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_column6 of table test.TestTable trx id 102973 lock_mode X waiting

Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 0

0: len 3; hex 53454b; asc SEK;;

1: len 8; hex 80000000007e1452; asc ~ R;;

*** (2) TRANSACTION:

TRANSACTION 102972, ACTIVE 26 sec starting index read

mysql tables in use 3, locked 3

219 lock struct(s), heap size 24784, 2906 row lock(s), undo log entries 7

MySQL thread id 5, OS thread handle 140024996841216, query id 84 localhost us updating

UPDATE TestTable

SET Column1 = 1,

Column2 = sysdate(),

Column3 = '026'

Column4 = 0

AND Column5 = 485

AND Column6 = 'SEK'

*** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 417 page no 1493 n bits 1000 index idx_Column6 of table test.TestTable trx id 102972 lock_mode X

Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0

0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 859 PHYSICAL RECORD: n_fields 2; compact format; info bits 0

0: len 3; hex 53454b; asc SEK;;

1: len 8; hex 80000000007e1452; asc ~ R;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 601 page no 89642 n bits 1000 index idx_column6 of table test.TestTable trx id 32231892482 lock_mode X locks rec but not gap waiting

Record lock, heap no 38 PHYSICAL RECORD: n_fields 2; compact format; info bits 0

0: len 3; hex 53454b; asc SEK;;

1: len 8; hex 80000000007eea14; asc ~ ;;

大致一看,更新同一索引的同一行,应该是一个Block,报TimeOut的错才对,怎么会报DeadLock?

【初步分析】

先分析下(2) TRANSACTION,TRANSACTION 32231892482。

等待的锁信息为:

0: len 3; hex 53454b; asc SEK;;

1: len 8; hex 80000000007eea14; asc

持有的锁信息为:

0: len 3; hex 53454b; asc SEK;;

1: len 8; hex 80000000007eeac4; asc

再先分析下(1) TRANSACTION,TRANSACTION 32231892617。

等待的锁信息为:

0: len 3; hex 53454b; asc SEK;;

1: len 8; hex 80000000007eeac4; asc

于是可以画出的死锁表,两个资源相互依赖,造成死锁:

TRANSACTION Hold Wait
32231892617 53454b\80000000007eea14 53454b\80000000007eeac4
32231892482 53454b\80000000007eeac4 53454b\80000000007eea14

让我们再看一下explain结果:

mysql>desc UPDATE TestTable SET Column1=1, Column2 = sysdate(),Column3 = '025' Column4 = 0 AND Column5 = 477 AND Column6 = 'SEK' \G;

*************************** 1. row ***************************

id: 1

select_type: UPDATE

table: TestTable

partitions: NULL

type: index_merge

possible_keys: column5_index,idx_column5_column6_Column1,idxColumn6

key: column5_index,idxColumn6

key_len: 8,9

ref: NULL

rows: 7

filtered: 100.00

Extra: Using intersect(column5_index,idxColumn6); Using where

可以看到 EXTRA 列:

Using intersect(column5_index,idxColumn6)

从5.1开始,引入了 index merge 优化技术,对同一个表可以使用多个索引分别进行条件扫描。

相关文档:http://dev.mysql.com/doc/refman/5.7/en/index-merge-optimization.html

The Index Merge method is used to retrieve rows with several range scans and to merge their results into one. The merge can produce unions, intersections, or unions-of-intersections of its underlying scans. This access method merges index scans from a single table; it does not merge scans across multiple tables.

【模拟与验证】

根据以上初步分析,猜测应该就是intersect造成的,于是在测试环境模拟验证,开启2个session模拟死锁:

时间序列 Session1 Session2
1 Begin;
2 UPDATE TestTable SET Column2 = sysdate() Column4 = 0 AND Column5 = 47 AND Column6 = 'SEK 
执行成功,影响7行
3 Begin;
4 UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
被Blocking
5 UPDATE TestTable SET Column2 = sysdate(),Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK';
执行成功
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

依据以上信息可以发现Session2虽然被Block了,但也获取了一些Session1在时间序列5时所需资源的X锁,可以再开启一个查询select count(Column5) from TestTable where Column5 = 485,设置SET TRANSACTION ISOLATION LEVEL SERIALIZABLE,去查询Column5 = 485的行,观察锁等待的信息:
mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id

mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, b.trx_query blocking_query FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id \G;

*************************** 1. row ***************************

waiting_trx_id: 103006

waiting_thread: 36

waiting_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK'

blocking_trx_id: 103003

blocking_thread: 37

blocking_query: NULL

*************************** 2. row ***************************

waiting_trx_id: 421500433538672

waiting_thread: 39

waiting_query: select count(Column5) from TestTable where Column5 = 485

blocking_trx_id: 103006

blocking_thread: 36

blocking_query: UPDATE TestTable SET Column1 = 1, Column2 = sysdate(), Column3 = '026' Column4 = 0 AND Column5 = 485 AND Column6 = 'SEK'

2 rows in set, 1 warning (0.00 sec)

mysql> select * from information_schema.innodb_lock_waits \G;

*************************** 1. row ***************************

requesting_trx_id: 103006

requested_lock_id: 103006:417:1493:859

blocking_trx_id: 103003

blocking_lock_id: 103003:417:1493:859

*************************** 2. row ***************************

requesting_trx_id: 421500433538672

requested_lock_id: 421500433538672:417:749:2

blocking_trx_id: 103006

blocking_lock_id: 103006:417:749:2

2 rows in set, 1 warning (0.00 sec)
mysql> select * from INNODB_LOCKS \G;

*************************** 1. row ***************************

lock_id: 103006:417:1493:859

lock_trx_id: 103006

lock_mode: X

lock_type: RECORD

lock_table: test.TestTable

lock_index: idxColumn6

lock_space: 417

lock_page: 1493

lock_rec: 859

lock_data: 'SEK', 8262738

*************************** 2. row ***************************

lock_id: 103003:417:1493:859

lock_trx_id: 103003

lock_mode: X

lock_type: RECORD

lock_table:test.TestTable

lock_index: idxColumn6

lock_space: 417

lock_page: 1493

lock_rec: 859

lock_data: 'SEK', 8262738

*************************** 3. row ***************************

lock_id: 421500433538672:417:749:2

lock_trx_id: 421500433538672

lock_mode: S

lock_type: RECORD

lock_table: test.TestTable

lock_index: column5_index

lock_space: 417

lock_page: 749

lock_rec: 2

lock_data: 485, 8317620

*************************** 4. row ***************************

lock_id: 103006:417:749:2

lock_trx_id: 103006

lock_mode: X

lock_type: RECORD

lock_table: test.TestTable

lock_index: column5_index

lock_space: 417

lock_page: 749

lock_rec: 2

lock_data: 485, 8317620

4 rows in set, 1 warning (0.00 sec)

可以看到Session2,trx_id 103006阻塞了trx_id 421500433538672,而trx_id 421500433538672 requested_lock也正好是lock_data: 485, 8317620。由此可见Session2虽然别block了,但是还是获取到了Index column5_index相关的锁。被Block是因为intersect的原因,还需要idxColumn6的锁,至此思路已经清晰,对整个分配锁的信息简化一下,如下表格(请求到的锁用青色表示,需获取但未获取到的锁用红色表示):

时间点 Session1 Session2
1 477 SEK
2 485 SEK
3 485 SEK 死锁发生

可以看到485 SEK这两个资源形成了一个环状,最终发生死锁。

【解决方法】

  • 最佳的方法是添加column5和Column6的联合索引。
  • 我们环境当时的情况发现Column6的筛选度非常低,就删除了Column6的索引。
    10:55左右删除索引后,报错没有再发生:

总结

以上就是这篇文章的全部内容了,希望本文的内容对大家的学习或者工作具有一定的参考学习价值,如果有疑问大家可以留言交流,谢谢大家对我们的支持。

(0)

相关推荐

  • 一次MySQL慢查询导致的故障

    我们知道分析MySQL语句查询性能的方法除了使用EXPLAIN 输出执行计划,还可以让MySQL记录下查询超过指定时间的语句,我们将超过指定时间的SQL语句查询称为"慢查询". 一. 起因 研发反应某台数据库僵死,后面的会话要么连接不上,要么要花费大量的时间返回结果,哪怕是一个简单的查询. 二. 处理 首先去监控平台查看服务器以及数据库状态,发现这台数据库有大量的慢查询.继续看服务器监控,CPU 平均使用率较高,IO 读写平均值正常.登录到 MySQL,使用 SHOW PROCESSL

  • MySQL下高可用故障转移方案MHA的超级部署教程

    MHA介绍 MHA是一位日本MySQL大牛用Perl写的一套MySQL故障切换方案,来保证数据库系统的高可用.在宕机的时间内(通常10-30秒内),完成故障切换,部署MHA,可避免主从一致性问题,节约购买新服务器的费用,不影响服务器性能,易安装,不改变现有部署.      还支持在线切换,从当前运行master切换到一个新的master上面,只需要很短的时间(0.5-2秒内),此时仅仅阻塞写操作,并不影响读操作,便于主机硬件维护.   在有高可用,数据一致性要求的系统上,MHA 提供了有用的功能

  • MYSQL主从库不同步故障一例解决方法

    于是: 1.在主库中创建一个临时库,将需要导入的表文件复制过来 2.执行 create database tmpdb; create table tmptable; cp mysql_date_file master_data_file //shell command 复制数据表文件到master data_dir下 insert into master.tmptable select * from tmpdb.tmptable; 执行完后,主库中数据导入正常 再看slave status sh

  • MySQL复制的概述、安装、故障、技巧、工具(火丁分享)

    同MongoDB,Redis这样的NoSQL数据库的复制相比,MySQL复制显得相当复杂! 概述 首先主服务器把数据变化记录到主日志,然后从服务器通过I/O线程读取主服务器上的主日志,并且把它写入到从服务器的中继日志中,接着SQL线程读取中继日志,并且在从服务器上重放,从而实现MySQL复制.具体如下图所示: 整个过程反映到从服务器上,对应三套日志信息,可在从服务器上用如下命令查看: 复制代码 代码如下: mysql> SHOW SLAVE STATUS; Master_Log_File &

  • 检测MySQL的表的故障的方法

    表的故障检测和修正的一般过程如下: 检查出错的表.如果该表检查通过,则完成任务,否则必须修复出错的数据库表. 在开始修复之前对表文件进行拷贝,以保证数据的安全. 开始修复数据库表. 如果修复失败,从数据库的备份或更新日志中恢复数据. 在使用myisamchk或isamchk检查或修复表之前,应该首先注意: 建立数据库备份和使用更新日志,以防修复失败,丢失数据. 仔细阅读本章内容以后再进行操作,尤其是不应该在阅读"避免与MySQL服务器交互作用"之前进行操作.因为,在你没有足够的知识之前

  • mysql报错:Deadlock found when trying to get lock; try restarting transaction的解决方法

    发现问题 最近在补以前数据的时候程序突然报如下错误: [2017-02-10 13:12:06.678] [INFO] mysqlLog - update tbl_playerdata_error: { [Error: ER_LOCK_DEADLOCK: Deadlock found when trying to get lock; try restarting transaction] code: 'ER_LOCK_DEADLOCK', errno: 1213, sqlState: '4000

  • 线上MYSQL同步报错故障处理方法总结(必看篇)

    前言 在发生故障切换后,经常遇到的问题就是同步报错,数据库很小的时候,dump完再导入很简单就处理好了,但线上的数据库都150G-200G,如果用单纯的这种方法,成本太高,故经过一段时间的摸索,总结了几种处理方法. 生产环境架构图 目前现网的架构,保存着两份数据,通过异步复制做的高可用集群,两台机器提供对外服务.在发生故障时,切换到slave上,并将其变成master,坏掉的机器反向同步新的master,在处理故障时,遇到最多的就是主从报错.下面是我收录下来的报错信息. 常见错误 最常见的3种情

  • MySQL DeadLock故障排查全过程记录

    [作者] 刘博:携程技术保障中心数据库高级经理,主要关注Sql server和Mysql的运维和故障处理. [环境] 版本号:5.6.21 隔离级别:REPEATABLE READ [问题描述] 接到监控报警,有一个线上的应用DeadLock报错,每15分钟会准时出现,报错统计如下图: 登录Mysql服务器查看日志: mysql> show engine innodb status\G *** (1) TRANSACTION: TRANSACTION 102973, ACTIVE 11 sec

  • 最新Linux系统下安装MySql 5.7.17全过程及注意事项

    1.cd /usr/local/ ##进入local目录 2.cp /home/soft/MySQL-5.7.15-Linux-glibc2.5-x86_64.tar.gz /usr/local/ ##拷贝mysql压缩到local目录 3.cd /usr/local/ ##进入local目录 4.tar -xzvf mysql-5.7.15-linux-glibc2.5-x86_64.tar.gz ##解压mysql压缩包 5.mv mysql-5.7.15-linux-glibc2.5-x8

  • mysql 开启慢查询 如何打开mysql的慢查询日志记录

    mysql慢查询日志对于跟踪有问题的查询非常有用,可以分析出当前程序里有很耗费资源的sql语句,那如何打开mysql的慢查询日志记录呢? 其实打开mysql的慢查询日志很简单,只需要在mysql的配置文件里(windows系统是my.ini,linux系统是my.cnf)的[mysqld]下面加上如下代码: 复制代码 代码如下: log-slow-queries=/var/lib/mysql/slowquery.log long_query_time=2 注: log-slow-queries

  • mysql获取group by总记录行数的方法

    本文实例讲述了mysql获取group by总记录行数的方法,分享给大家供大家参考.具体方法分析如下: 一般来说,mysql获取group by内部可以获取到某字段的记录分组统计总数,而无法统计出分组的记录数. mysql中可以使用SQL_CALC_FOUND_ROWS来获取查询的行数,在很多分页的程序中都这样写: 复制代码 代码如下: SELECT COUNT(*) from `table` WHERE ......; 查出符合条件的记录总数: 复制代码 代码如下: SELECT * FROM

  • Mysql查询最近一条记录的sql语句(优化篇)

    下策--查询出结果后将时间排序后取第一条 select * from a where create_time<="2017-03-29 19:30:36" order by create_time desc limit 1 这样做虽然可以取出当前时间最近的一条记录,但是一次查询需要将表遍历一遍,对于百万以上数据查询将比较费时:limit是先取出全部结果,然后取第一条,相当于查询中占用了不必要的时间和空间:还有如果需要批量取出最近一条记录,比方说:"一个订单表,有用户,订

  • Golang操作MySql数据库的完整步骤记录

    前言 MySQL是业界常用的关系型数据库,在平时开发中会经常与MySql数据库打交道,所以在接下来将介绍怎么使用Go语言操作MySql数据库. 下载MySql连接驱动 Go语言中的database/sql包提供了保证SQL或类SQL数据库的泛用接口,并不提供具体的数据库驱动.使用database/sql包时必须注入(至少)一个数据库驱动. 我们常用的数据库基本上都有完整的第三方实现.比如:MySQL驱动 **下载依赖** go get -u github.com/go-sql-driver/my

  • 一次docker错误的耗时排查过程记录

    由来 客户是深信服的订制系统,基于 centos 改的,排查半天发现居然是文件损坏,而不是 docker 的问题. 环境信息 docker信息: $ docker info Containers: 0 Running: 0 Paused: 0 Stopped: 0 Images: 2 Server Version: 18.09.3 Storage Driver: overlay2 Backing Filesystem: xfs Supports d_type: true Native Overl

  • MySQL系列之十一 日志记录

    系列教程 MySQL系列之开篇 MySQL关系型数据库基础概念 MySQL系列之一 MariaDB-server安装 MySQL系列之二 多实例配置 MySQL系列之三 基础篇 MySQL系列之四 SQL语法 MySQL系列之五 视图.存储函数.存储过程.触发器 MySQL系列之六 用户与授权 MySQL系列之七 MySQL存储引擎 MySQL系列之八 MySQL服务器变量 MySQL系列之九 mysql查询缓存及索引 MySQL系列之十 MySQL事务隔离实现并发控制 MySQL系列之十一 日

  • IntelliJ IDEA 2021.3 正式发布之支持远程开发、IDE故障排查等多项优化改进

    昨天刚刚跟大家聊了Jetbrains即将推出轻量级编辑器Fleet,以挑战 VS Code的消息,今天又收到了IntelliJ IDEA 2021.3正式发布的推送. 不说废话,下面就跟我们一起来看看这个版本带来了哪些惊艳的功能! 远程开发 在这个版本中的远程开发还不是一个正式版本,而是BETA版,但通过这个BETA版本,也可以体验IDEA"远程开发"给我们带来的全新体验. 通过该功能的支持,我们可以从世界任何地方轻松连接到运行 IntelliJ IDEA 后端的远程计算机.所有处理都

  • j2Cache线上异常排查问题解决记录分析

    目录 问题背景 问题分析 假设问题 小心求证 问题重现 问题解决 问题后记-下面才是真正的原因 重新假设 最终解决 问题背景 开发反馈,线上有个服务在运行一段时间后,就会抛异常导致redis缓存不可用.项目使用了j2Caceh,异常是j2Cache的RedisCacheProvider抛出来的,如: Exception in thread "main" redis.clients.jedis.exceptions.JedisException: Could not get a reso

随机推荐