1、事件还原
昨天下午,收到一个504的告警,显然这是一个超时告警。当时由于手头有其他事情,没在意,就只是瞄了一眼,但是引起告警的方法很熟悉,是我写的,第一反应有点诧异。
诧异之后,继续处理手头的工作。
一小时过后,又收到同样的告警,显然不是偶尔,肯定是哪儿出问题了,于是开始排查。
报警的接口是一个Controller层ControllerA的getControllerAMethod接口,其调用了多个微服务,并最终拼装结果数据进行返回。出问题的是ServiceM,ServiceM服务里的getServiceMMethod方法逻辑也很简单,主要是两次数据库查询,从MySQL数据库取到数据并返回给调用方。
调用链如下图所示
2、环境介绍
语言:Go
DB:MySQL
数据库交互:database/sql(公司在此基础上做了一些定制和封装,本质还是database/sql)
下面开始介绍这个问题的具体排查过程。
3、本能反应:从sql语句入手
拿到告警,从告警信息和对应的日志详情信息来看,属于超时问题。
第一反应是查看sql语句是否是慢查询(虽然打心里知道这个可能性极低),sql语句很简单,形如
select a, b, c from tableA where a in (a1,a2,a3)
不看执行计划也知道是可以命中索引的。
但还是看了下执行计划和真实的执行情况,分析结果和响应时间都相当可观,没有任何问题。
本能反应的排查就是这么索然无味,开始下一步排查。
4、上游排查:是否context时间耗尽
既然是超时问题,有可能是上游超时,也可能是下游超时,第一步排查已经排除了下游因为慢查询导致超时的可能性。
那会不会是上游超时呢?显然是有可能的,毕竟我们知道Go的context可以一路传递下去,所有服务调用都共用设置的总的时间额度。
而且从上图可以发现ServiceM也是在上游接口的最后一步,所以如果上面的服务占用耗时过多,就会导致ServiceM的时间额度被压缩的所剩无几。
但是从日志排查可以发现,在ServiceM层看getServiceMethod方法对应sql查询几乎都是几十毫秒返回。
从这个情况来看,不像是因为上游时间不够导致的超时。
5、下游初步排查:rows成主要怀疑对象
既然上游时间额度充足,那问题还是大概率出在下游服务接口上。
于是开始仔细阅读getServiceMMethod方法代码,下面是代码功能的伪代码实现
rows, err = db.query(sql1)if err != nil { ...}defer rows.Close()for rows.Next() { rows.scan(...)}rows, err = db.query(sql2)if err != nil { ...}defer rows.Close()for rows.Next() { rows.scan(...)}
看完代码,开始有点小兴奋,我想没错了,大概就是这个rows的问题了。
在《Go组件学习——database/sql数据库连接池你用对了吗》这篇我主要介绍了有关rows没有正常关闭带来的坑。所以开始联想是否是因为在遍历rows过程中没有正确关闭数据库连接,造成连接泄露,以至于后面的查询拿不到连接导致超时。
原因我已经分析的清清楚楚,但是具体是哪一步除了问题呢,唯一能想到的是这里两次查询使用的是同一个rows对象,是不是某种情况导致在前一次已经关闭了连接而下一次查询直接使用了关闭的连接而导致超时呢?
此时报警开始越来越频繁,于是将这里两次查询由原来的一个rows接收改为使用两个rows分别接收并关闭,然后提交代码,测试通过后开始上线。
6、短暂的风平浪静
代码上线后,效果立竿见影。
告警立马停止,日志也没有再出现超时的信息了,一切又恢复到了往日的平静,这让我坚信,我应该是找到原因并解决问题了吧。
回到家后,心里还是有些不踏实,从11点开始,我拿出电脑,开始各种模拟、验证和还原告警的原因。
7、三小时后,意识到风平浪静可能是假象
从11点开始,一直到两点,整整三个小时,我不但没有找到原因,反而发现我的解决方式可能并没有解决问题。
因为出问题的代码并不复杂,如上所示,即只有两个Select查询。
于是我写了一段一样的代码在本地测试,跑完后并没有出现超时或者拿不到连接的情况。甚至,我将maxConn和IdleConn都设置为1也无不会出现超时。
除非,像文章《Go组件学习——database/sql数据库连接池你用对了吗》里说的一样,在row.Next()过程中提前退出且没有rows.Close()语句,才会造成下一次查询拿不到连接的情况,即如下代码所示
func oneConnWithRowsNextWithError() {db, _ := db.Open("mysql