记一次忘记 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
// 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,满了之后后面的请求就只能等前面连接释放,但是前面的连接都泄露了,没法被管理到,永远不会被释放。
究竟是哪里泄露了呢?能想到的有两种:
- 事务没有关闭,比如忘记提交或回滚
- Rows() 忘记 Close
第一种简单,在MySQL server 看下有没有未关闭的事务,无。 第二种从堆栈上看不出来,只能排查代码,结果业务团队还真找到一处忘记Close Rows(), 改完就没问题了。
回过头来看,还是仔细看堆栈,从堆栈上看应该第一次就能找到根因。
给业务团队的建议:
- 加上超时,包括dsn 的各种timeout 以及每次通过context 传递超时;
- 使用lint 提前发现这类问题,golangci-lint 就有 bodyclose 和 sqlclosecheck 。
Read other posts