mysql invalid conn排查

举报
蓝胖子的编程梦 发表于 2023/05/25 18:10:52 2023/05/25
【摘要】 mysql invalid conn排查服务监控系列文章服务监控系列视频 问题背景服务使用golang ,客户端库是go-mysql-driver ,系统测试环境频繁但是不总是报出invalid conn 错误,但实际拿sql执行时却是正常执行。 排查思路 原因分析 客户端使用了无效连接由于连接无效,首先考虑客户端使用了过期连接。mysql服务器端和客户端都能配置各自连接的最大生命周期。如...

mysql invalid conn排查

服务监控系列文章

服务监控系列视频

问题背景

服务使用golang ,客户端库是go-mysql-driver ,系统测试环境频繁但是不总是报出invalid conn 错误,但实际拿sql执行时却是正常执行。

排查思路

原因分析

客户端使用了无效连接

由于连接无效,首先考虑客户端使用了过期连接。

mysql服务器端和客户端都能配置各自连接的最大生命周期。

如果客户端配置的连接最大生命周期大于服务端,并且客户端没有无效连接重连的机制,则会导致服务端的连接在过期以后,客户端使用已经过期的连接,从而引发invalid conn。

查询mysql 连接的最大空闲生命周期 s为单位

show global variables like 'wait_timeout';

image.png
客户端最大生命周期配置

db.SetConnMaxLifetime(time.Duration(timeout) * time.Hour) //reconnect after 1 hour

mysql server的最大生命周期大于golang客户端的连接最大生命周期,所以排除此原因。

连接被莫名的原因关掉了,抓包分析

一时间陷入僵局,连接究竟是为何无效。直接抓包分析。

sudo tcpdump -i lo port 3306 -w conn.pcap

专家系统发现异常包

将pcap文件用wireshark打开,用专家系统对抓到的包做一个整体的分析。
看到有8个异常的RST包,正常的连接开关是不会有RST产生的,着重分析下RST产生的原因。

image.png

发现问题

image.png看到具体发生异常的地方,mysql服务器在回复客户端一个ACK消息后,客户端等了10s对mysql服务器发起了Request Quit(mysql 协议)关闭连接的命令。

具体看下异常前后。
选择菜单栏的Statistics->Flow Graph,就可以打开数据流图窗口。
image.png可以看到过程如下:
1,11:55:49.05 在客户端向mysql 发起 Request Execute Statement 执行sql的命令,
2,mysql 恢复Ack
3, 但是mysql并没有把执行结果返回给客户端,所以客户端等待了10s后发起关闭连接的命令。
4,mysql 在11:55:59.27才返回了执行结果。
5,但是这个时候客户端已经把连接关闭了,对已经关闭的连接发送数据触发了RST信号,所以客户端回应服务器RST

看到这里,已经可以很明确的任务是服务器执行sql超时了,或者说是服务器返回结果时超时了。

回到客户端代码确认报错原因

在进一步,是不是超时导致的报警呢?
可以看到在读取缓冲区数据时,有可能报出ErrInvalidConn

// read packet header
		data, err := mc.buf.readNext(4)
		if err != nil {
			if cerr := mc.canceled.Value(); cerr != nil {
				return nil, cerr
			}
			errLog.Print(err)
			mc.Close()
			return nil, ErrInvalidConn
		}

继续查看mc.buf.readNext,发现超时代码

if b.timeout > 0 {
			if err := b.nc.SetReadDeadline(time.Now().Add(b.timeout)); err != nil {
				return err
			}
		}

mysql受到什么因素导致sql过长

因为是数据库,首先想到了磁盘,再次回到top,iostat ,iotop分析。
此次发现异常。
image.png发现磁盘io使用率偶尔会飙高,所以mysql执行速率受到了影响。

解决问题

占用磁盘使用率的几个项目主要是视频转码项目,转码的时间不是固定的,所以当转码的时候,在同一台主机上的mysql受到了影响,引发了超时,导致应用层报出invalid conn 错误。

经过确认,测试环境可暂时关闭转码功能,关闭后,再也没有报警出现。

正常情况下,当抓包看到mysql返回超时是,应该立即就去看系统io等硬件指标了,这里由于是测试环境,所以我还是去看了go-mysql-client 库的代码,进一步确认。

反思

测试环境监控体系不够完善,没有监控界面,不然应该一眼能看出磁盘io异常。

其次是回归到应用层看代码的时机较晚,还是被invalid conn迷惑了,其实如果go-mysql库报错为超时错误可能会更符合这个场景。

其实从一开始,就用了top和iostat 去分析系统磁盘占用情况,但是由于那段时间内指标并无异常,加上报错信息是invalid conn 导致我首先把问题定位到是网络连接上出的问题,并抓包分析。
看到这种偶发的错误,应该持续性的观察系统指标,这次只是看了十几秒钟就转而去分析其他因素了,实属不该。

测试环境开启慢日志

show variables like 'slow_query%';

image.png
开启慢日志

set global slow_query_log=1 
【版权声明】本文为华为云社区用户原创内容,转载时必须标注文章的来源(华为云社区)、文章链接、文章作者等基本信息, 否则作者和本社区有权追究责任。如果您发现本社区中有涉嫌抄袭的内容,欢迎发送邮件进行举报,并提供相关证据,一经查实,本社区将立刻删除涉嫌侵权内容,举报邮箱: cloudbbs@huaweicloud.com
  • 点赞
  • 收藏
  • 关注作者

评论(0

0/1000
抱歉,系统识别当前为高风险访问,暂不支持该操作

全部回复

上滑加载中

设置昵称

在此一键设置昵称,即可参与社区互动!

*长度不超过10个汉字或20个英文字符,设置后3个月内不可修改。

*长度不超过10个汉字或20个英文字符,设置后3个月内不可修改。