admin管理员组

文章数量:1030687

一个死锁导致的invalid connection问题排查

1. 背景

上周社区业务的开发同学反馈他负责的Go应用请求Mysql时不时会报错invalid connection，一直排查不到原因，因此我帮他排查了下，最终发现是一个比较典型的死锁问题，因此记录下排查过程与思路。

首先看下监控报错：

image.png

涉及到的SQL:

代码语言：javascript代码运行次数：0运行复制
UPDATE `article_meta` SET `meta_id`=?,`meta_value`=?,`update_time`=? WHERE `meta_id` = ?

表结构

代码语言：javascript代码运行次数：0运行复制
CREATE TABLE `article_meta` (
  `meta_id` bigint(20) NOT NULL AUTO_INCREMENT,
  `article_id` bigint(20) unsigned NOT NULL DEFAULT '0',
  `meta_key` varchar(255) DEFAULT NULL,
  `meta_value` mediumtext,
  `update_time` datetime NOT NULL DEFAULT '0000-00-00 00:00:00' COMMENT '更新时间',
  PRIMARY KEY (`meta_id`),
  KEY `article_id` (`article_id`),
  KEY `meta_key` (`meta_key`)
) ENGINE = InnoDB

2. 排查思路

2.1 根因分析

从invalid connection这个报错信息上首先猜测是Mysql连接的问题，因此到database/sql包下看看哪些位置会报这个错误，通过全文检索并没有发现有这个错误msg。那么继续到Mysql的驱动go-sql-driver/mysql包中查询，最终发现了可能报这个错误的位置大概有两处：

  1. 事务提交和回滚时如果连接已关闭会报这个错误
image.png
  1. 读包时遇到错误（连接被关闭、超时）会报这个错误
image.png

结合监控上的报错信息与业务同学配置的readTimeout超时时间基本确认是SQL执行超时导致了readPacket()抛出的错误。

image.png

另外readPacket()函数中抛出ErrInvalidConn之前会调用mc.log(err)打印错误信息，打日志实际是使用了defaultLogger打印到了标准输出中:

image.png

查询Pod的标准输出之后确实看到了如下输出，进一步佐证了上述的结论

image.png

2.2 慢SQL分析

那么我们再回头看执行的SQL，分析下执行慢SQL的原因

代码语言：javascript代码运行次数：0运行复制
UPDATE `article_meta` SET `meta_id`=?,`meta_value`=?,`update_time`=? WHERE `meta_id` = ?

结合表结构可以知道meta_id是主键id，那么这个SQL执行慢不太可能是查询行数据导致的，那么只剩下一种可能：这个SQL在等待锁释放。

SQL执行超过了3000ms，意味着可能存在一个慢事务，锁住该行后执行超过了3000ms，但询问业务同学后得知更新这个表的只有这一个位置。

这时我们再review遍业务代码，尝试从业务代码中找到写蛛丝马迹，代码精简后大概是如下逻辑:

代码语言：javascript代码运行次数：0运行复制
var articleMetaUpdateMap map[string]*UpdateData
...
tx := db.Begin()
for _, value := range articleMetaUpdateMap {
	MetaID := value.MetaID
	err = tx.Table("article_meta").Where("meta_id = ? ", MetaID).Updates(value).Error
	if err != nil {
		tx.Rollback()
		return
	}
}

由于Go map的元素遍历随机性，这个代码逻辑可能会造成如下的执行顺序 | 事务A | 事务B | | - | - | | Update article_meta value=x where meta_id = 1 （锁定了id=1的行）| | | | Update article_meta value=x where meta_id = 2 （锁定了id=2的行）| | Update article_meta value=x where meta_id = 2 (locked，等待事务B释放id=2行锁) | | | | Update article_meta value=x where meta_id = 1 (locked，等待事务A释放id=1行锁) |

好，两个事务互相等待对方释放行锁，一个典型的死锁~

2.3 一些问题

  1. 那么为什么Mysql检测到死锁呢？

很简单，这个业务库没有开启死锁检测

代码语言：javascript代码运行次数：0运行复制
> SHOW VARIABLES LIKE 'innodb_deadlock_detect';
Variable_name | Value
innodb_deadlock_detect | OFF
  1. 通过SHOW FULL PROCESSLIST查询运行中的线程是不是应该观测到两个线程？

答案是观测不到的，原因是readPacket()超时后会主动关闭连接

代码语言：javascript代码运行次数：0运行复制
data, err := mc.buf.readNext(4)
if err != nil {
    ...
	mc.log(err)
	mc.Close() // 关闭了连接
	return nil, ErrInvalidConn
}

3. 修复方案

在遍历要更新的数据即articleMetaUpdateMap这个map之前，将其转成数组，然后按照主键Id排个序（正序倒序都可），这样可以保证两个事务以相同的上锁顺序进行更新，避免了死锁。

本文参与 腾讯云自媒体同步曝光计划，分享自作者个人站点/博客。 原始发表：2025-04-14，如有侵权请联系 cloudcommunity@tencent 删除连接事务数据connectionmeta

一个死锁导致的invalid connection问题排查

1. 背景

上周社区业务的开发同学反馈他负责的Go应用请求Mysql时不时会报错invalid connection，一直排查不到原因，因此我帮他排查了下，最终发现是一个比较典型的死锁问题，因此记录下排查过程与思路。

首先看下监控报错：

image.png

涉及到的SQL:

代码语言：javascript代码运行次数：0运行复制
UPDATE `article_meta` SET `meta_id`=?,`meta_value`=?,`update_time`=? WHERE `meta_id` = ?

表结构

代码语言：javascript代码运行次数：0运行复制
CREATE TABLE `article_meta` (
  `meta_id` bigint(20) NOT NULL AUTO_INCREMENT,
  `article_id` bigint(20) unsigned NOT NULL DEFAULT '0',
  `meta_key` varchar(255) DEFAULT NULL,
  `meta_value` mediumtext,
  `update_time` datetime NOT NULL DEFAULT '0000-00-00 00:00:00' COMMENT '更新时间',
  PRIMARY KEY (`meta_id`),
  KEY `article_id` (`article_id`),
  KEY `meta_key` (`meta_key`)
) ENGINE = InnoDB

2. 排查思路

2.1 根因分析

从invalid connection这个报错信息上首先猜测是Mysql连接的问题，因此到database/sql包下看看哪些位置会报这个错误，通过全文检索并没有发现有这个错误msg。那么继续到Mysql的驱动go-sql-driver/mysql包中查询，最终发现了可能报这个错误的位置大概有两处：

  1. 事务提交和回滚时如果连接已关闭会报这个错误
image.png
  1. 读包时遇到错误（连接被关闭、超时）会报这个错误
image.png

结合监控上的报错信息与业务同学配置的readTimeout超时时间基本确认是SQL执行超时导致了readPacket()抛出的错误。

image.png

另外readPacket()函数中抛出ErrInvalidConn之前会调用mc.log(err)打印错误信息，打日志实际是使用了defaultLogger打印到了标准输出中:

image.png

查询Pod的标准输出之后确实看到了如下输出，进一步佐证了上述的结论

image.png

2.2 慢SQL分析

那么我们再回头看执行的SQL，分析下执行慢SQL的原因

代码语言：javascript代码运行次数：0运行复制
UPDATE `article_meta` SET `meta_id`=?,`meta_value`=?,`update_time`=? WHERE `meta_id` = ?

结合表结构可以知道meta_id是主键id，那么这个SQL执行慢不太可能是查询行数据导致的，那么只剩下一种可能：这个SQL在等待锁释放。

SQL执行超过了3000ms，意味着可能存在一个慢事务，锁住该行后执行超过了3000ms，但询问业务同学后得知更新这个表的只有这一个位置。

这时我们再review遍业务代码，尝试从业务代码中找到写蛛丝马迹，代码精简后大概是如下逻辑:

代码语言：javascript代码运行次数：0运行复制
var articleMetaUpdateMap map[string]*UpdateData
...
tx := db.Begin()
for _, value := range articleMetaUpdateMap {
	MetaID := value.MetaID
	err = tx.Table("article_meta").Where("meta_id = ? ", MetaID).Updates(value).Error
	if err != nil {
		tx.Rollback()
		return
	}
}

由于Go map的元素遍历随机性，这个代码逻辑可能会造成如下的执行顺序 | 事务A | 事务B | | - | - | | Update article_meta value=x where meta_id = 1 （锁定了id=1的行）| | | | Update article_meta value=x where meta_id = 2 （锁定了id=2的行）| | Update article_meta value=x where meta_id = 2 (locked，等待事务B释放id=2行锁) | | | | Update article_meta value=x where meta_id = 1 (locked，等待事务A释放id=1行锁) |

好，两个事务互相等待对方释放行锁，一个典型的死锁~

2.3 一些问题

  1. 那么为什么Mysql检测到死锁呢？

很简单，这个业务库没有开启死锁检测

代码语言：javascript代码运行次数：0运行复制
> SHOW VARIABLES LIKE 'innodb_deadlock_detect';
Variable_name | Value
innodb_deadlock_detect | OFF
  1. 通过SHOW FULL PROCESSLIST查询运行中的线程是不是应该观测到两个线程？

答案是观测不到的，原因是readPacket()超时后会主动关闭连接

代码语言：javascript代码运行次数：0运行复制
data, err := mc.buf.readNext(4)
if err != nil {
    ...
	mc.log(err)
	mc.Close() // 关闭了连接
	return nil, ErrInvalidConn
}

3. 修复方案

在遍历要更新的数据即articleMetaUpdateMap这个map之前，将其转成数组，然后按照主键Id排个序（正序倒序都可），这样可以保证两个事务以相同的上锁顺序进行更新，避免了死锁。

本文参与 腾讯云自媒体同步曝光计划，分享自作者个人站点/博客。 原始发表：2025-04-14，如有侵权请联系 cloudcommunity@tencent 删除连接事务数据connectionmeta

本文标签： 一个死锁导致的invalid connection问题排查

版权声明：本文标题：一个死锁导致的invalid connection问题排查 内容由热心网友自发贡献，该文观点仅代表作者本人， 转载请联系作者并注明出处：http://it.en369.cn/jiaocheng/1747679625a2202991.html， 本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如发现本站有涉嫌抄袭侵权/违法违规的内容，一经查实，本站将立刻删除。