记一次忘记 close rows 引发的惨案

这周帮业务团队排查一个Go 服务问题,这里记录下。

问题现象是:Go 写的HTTP 服务, 每隔几小时接口就会卡死,得重启进程才能恢复。

老规矩,先上pprof, 有一半goroutine 都卡在MySQL 和 一个锁。

看代码发现,MySQL Client 用的是 gorm, 没设置超时。。。 再叠加某个接口先获取个全局锁,再查询MySQL,如果第一个请求阻塞了,后面请求就一直在等锁。。。查完我就潇洒得走了。

第二天业务又找来,加了超时还是没用。

pprof 显示还是有一半goroutine 阻塞在MySQL,然后怀疑是MySQL server 有问题。找来MySQL 同事一起排查。

一顿抓包,发现阻塞期间压根就没有网络流量,那就排除MySQL server 问题了。

仔细看goroutine 堆栈, 都阻塞在 database/sql/sql.go#L1312

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
 // Out of free connections or we were asked not to use one. If we're not
// allowed to open any more connections, make a request and wait.
if db.maxOpen > 0 && db.numOpen >= db.maxOpen {
// Make the connRequest channel. It's buffered so that the
// connectionOpener doesn't block while waiting for the req to be read.
req := make(chan connRequest, 1)
reqKey := db.nextRequestKeyLocked()
db.connRequests[reqKey] = req
db.waitCount++
db.mu.Unlock()

waitStart := nowFunc()

// Timeout the connection request with the context.
select {
case <-ctx.Done():
// Remove the connection request and ensure no value has been sent
// on it after removing.
db.mu.Lock()
delete(db.connRequests, reqKey)
db.mu.Unlock()

atomic.AddInt64(&db.waitDuration, int64(time.Since(waitStart)))

select {
default:
case ret, ok := <-req:
if ok && ret.conn != nil {
db.putConn(ret.conn, ret.err, false)
}
}
return nil, ctx.Err()

好家伙,原来是连接泄露了,maxOpen 设置的100,满了之后后面的请求就只能等前面连接释放,但是前面的连接都泄露了,没法被管理到,永远不会被释放。

究竟是哪里泄露了呢?能想到的有两种:

  1. 事务没有关闭,比如忘记提交或回滚
  2. Rows() 忘记 Close

第一种简单,在MySQL server 看下有没有未关闭的事务,无。
第二种从堆栈上看不出来,只能排查代码,结果业务团队还真找到一处忘记Close Rows(), 改完就没问题了。

回过头来看,还是仔细看堆栈,从堆栈上看应该第一次就能找到根因。

给业务团队的建议:

  1. 加上超时,包括dsn 的各种timeout 以及每次通过context 传递超时;
  2. 使用lint 提前发现这类问题,golangci-lint 就有 bodyclose 和 sqlclosecheck 。