go通过sqlx使用事务导致的goroutine泄露问题记录

问题的起因是收到预警,某个服务的请求持续出现504,而服务本身的记录没有504记录,触发的是负载均衡超时
最终通过pprof定位到了问题并解决

go版本为14
通过pprof查看,好家伙,goroutine数4W+,如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
goroutine profile: total 40269
30633 @ 0x432aa0 0x44224b 0x9ca93c 0x9cd106 0x9cce51 0x9e349e 0x9e3432 0x9e5d5d 0xa17457 0xa17365 0xa32339 0xaa6c26 0xa9f333 0xa81bea 0xa9bae4 0xa9c42e 0xa7a2e2 0x740254 0x73bbf5 0x45fd51
# 0x9ca93b database/sql.(*DB).conn+0x7ab /usr/local/go/src/database/sql/sql.go:1183
# 0x9cd105 database/sql.(*DB).query+0x65 /usr/local/go/src/database/sql/sql.go:1565
# 0x9cce50 database/sql.(*DB).QueryContext+0xd0 /usr/local/go/src/database/sql/sql.go:1547
# 0x9e349d database/sql.(*DB).Query+0x8d /usr/local/go/src/database/sql/sql.go:1561
# 0x9e3431 github.com/jmoiron/sqlx.(*DB).QueryRowx+0x21 /go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:363
# 0x9e5d5c github.com/jmoiron/sqlx.Get+0x6c /go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:685
# 0xa17456 github.com/jmoiron/sqlx.(*DB).Get+0x246 /go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:328
...业务代码
# 0xa81be9 github.com/labstack/echo.(*Echo).Add.func1+0x89 /go/pkg/mod/github.com/labstack/echo@v3.3.10+incompatible/echo.go:490
# 0xa9bae3 github.com/labstack/echo/middleware.LoggerWithConfig.func2.1+0x123 /go/pkg/mod/github.com/labstack/echo@v3.3.10+incompatible/middleware/logger.go:118
# 0xa9c42d github.com/labstack/echo/middleware.RecoverWithConfig.func1.1+0x10d /go/pkg/mod/github.com/labstack/echo@v3.3.10+incompatible/middleware/recover.go:78
# 0xa7a2e1 github.com/labstack/echo.(*Echo).ServeHTTP+0x221 /go/pkg/mod/github.com/labstack/echo@v3.3.10+incompatible/echo.go:593
# 0x740253 net/http.serverHandler.ServeHTTP+0xa3 /usr/local/go/src/net/http/server.go:2802
# 0x73bbf4 net/http.(*conn).serve+0x874 /usr/local/go/src/net/http/server.go:1890

pod的内存占用也从200M持续飙升到2G,且持续增加
其它的协程也都是阻塞在了 /usr/local/go/src/database/sql/sql.go:1183,代码简化如下

1
2
3
4
5
6
7
8
select {
case <-ctx.Done():
....
return nil, ctx.Err()
case ret, ok := <-req:
....
return ret.conn, ret.err
}

此代码并无bug(不要首先怀疑开源代码),最终根据实际的协程池配置,找到了可疑的数据,以及16个独立的,且未增长变化的conn连接阻塞(同上)

1
2
16 @ 0x432aa0 0x407708 0x4076de 0x4073cb 0x9cf20b 0x45fd51
# 0x9cf20a database/sql.(*Tx).awaitDone+0x4a /usr/local/go/src/database/sql/sql.go:2002

1
2
16 @ 0x432aa0 0x44224b 0xad7f9f 0x45fd51
# 0xad7f9e github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1+0xbe /go/pkg/mod/github.com/go-sql-driver/mysql@v1.5.0/connection.go:621

根据几个数据,最终确定了问题原因是连接池被错误的耗尽

原因

  1. 次要,事务未设置超时,直接调用 Beginx(),未通过上下文设置超时时间
  2. 次要,http请求未设置超时时间
  3. 次要,连接池设置为

    1
    2
    db.SetMaxOpenConns(16)
    db.SetMaxIdleConns(8)
  4. 主要,伪代码如下

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    tx, err := db.Beginx()
    if err != nil {
    return ErrSQLUpdate
    }

    err = callOtherFunc1()
    ...
    err = callOtherFunc2()

    if err != nil {
    tx.Rollback()
    return err
    }

    return tx.Commit()

其中 callOtherFunc1 和 callOtherFunc2 方法中,通过db.Exec 执行了两条语句
此用法是错误的,应该使用 tx.Exec
原因是开启事务后,tx将绑定并控制一个connection,直到commit或rollback后release
所以如果不能正确释放连接,将导致连接泄露,资源无法回收
而导致此次问题的真正原因是db.Beginx开启了一个事务,即独控了一个connection,然后向下执行时,其它的语句又重新获取connection,导致一次执行最多同时获取两个connection
一般状态下不会有什么问题,也就是之前运行几个月没有问题的原因。但当此方法并发执行时,如极端下 16 个同时进行,此时16个事务开启,控制着16个连接,达到了 MaxOpenConns 限制
下面的方法再执行需要获取新的连接,而连接池的限制将要等待连接释放才能获取连接,此时逻辑死锁已经生成,其它的任何数据库请求都将处于排队状态

之所以服务没有超时记录,是因为所有的请求都处于等待状态

解决方法

  1. 给http请求设置超时时间,此为最后的保命手段,其它所有服务都应有合理设置
  2. 事务的初始化也要设置超时时间,所有使用事务的方法都应该确保设置有合理的超时时间
  3. 事务执行应该独立一个连接池,不与其它查询共用
  4. 要好好看文档,事务开启后要使用*Tx完成所有操作,文档中有明确的说明,当前的用法是无法实现事务控制预期的

参考链接

sqlx使用文档