这周帮业务团队排查一个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,满了之后后面的请求就只能等前面连接释放,但是前面的连接都泄露了,没法被管理到,永远不会被释放。

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

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

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

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

给业务团队的建议:

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