1. 问题与背景
最近公司内部准备尝试使用下腾讯的TDSQL,因此组内同学写了一段很简单的查询TDSQL的go web程序,使用ab对其进行一个简单压测以获取TDSQL的性能表现,go代码如下:
package main
import (
"crypto/md5"
"database/sql"
"fmt"
"log"
"math/rand"
"net/http"
"strconv"
"time"
"github.com/gin-gonic/gin"
_ "github.com/go-sql-driver/mysql"
)
func main() {
r := gin.New()
r.Use(gin.Logger())
r.GET("/test", func(c *gin.Context) {
c.JSON(200, gin.H{
"message": "test",
})
})
dbconnect, err := sql.Open("mysql", "user:passwd@tcp(10.43.0.43:3306)/dbname")
if err != nil {
panic(err)
}
dbconnect.SetMaxIdleConns(5)
dbconnect.SetMaxOpenConns(10)
dbconnect.SetConnMaxLifetime(time.Hour)
dbconnect.SetConnMaxIdleTime(time.Hour)
r.GET("tdsql_test", func(context *gin.Context) {
muid := fmt.Sprintf("%x", md5.Sum([]byte(strconv.Itoa(rand.Intn(1000000000000)))))
rows, err := dbconnect.Query(fmt.Sprintf("select muid from rtb_channel_0 where muid='%s'", muid))
if err != nil {
log.Fatal(err)
context.JSON(http.StatusInternalServerError, gin.H{
"error_code": -3,
})
return
}
rows.Close()
context.JSON(http.StatusOK, gin.H{
"error_code": 0,
"error_msg": muid,
"data": "result",
})
})
r.Run(":9000")
}
ab压测命令如下:
ab -c 10 -n 500000 "http://127.0.0.1:9000/tdsql_test"
压测开始不久之后代码log.Fatal(err)
就打印出了错误信息并退出了:
dial tcp 10.43.0.43:3306: connect: cannot assign requested address
这段错误信息是说无法连接到10.43.0.43:3306 ,原因是无法分配请求地址号,就是说本地端口号都被占用了。那么我们就开始进行排查,端口号究竟是被谁占满的?
2. 排查过程
2.1 通过netstat命令查看端口都被谁占用
netstat -nta | grep 10.43.0.43
有如下输出:
可以看到有大量处于TIME_WAIT
状态的TCP连接,这些连接占用了大量的端口。那么这些TIMI_WAIT
状态的TCP连接是从哪来的呢?
为了弄清楚这个问题,我们必须知道TIME_WAIT
状态是怎么回事。
2.1.1 TIME_WAIT
上图是经典的TCP四次挥手断开连接的过程。可以看到在四次挥手的过程中,主动关闭连接的一端在收到对端发送的FIN包之后会进入TIME_WAIT状态,会等待2MSL之后才能真正关闭连接。
MSL: 最长报文段寿命(Maximum Segment Lifetime),是一个工程值(经验值),RFC标准是2分钟,不过有点太长了,一般是30秒,1分钟,2分钟。
为什么客户端TIME_WAIT状态等待2MSL呢?四次握手最后一步客户端向服务端响应ACK,后有两种情况:
- 服务端没有收到ACK,这时服务端会超时重传FIN
- 服务端收到了ACK,但是客户端不知道服务端有没有收到
无论1还是2,客户端都需要等待,要取这两种情况等待的最大值以应对最坏情况的发生,这个最坏的情况就是: 去向ACK消息的最大生存时间(MSL) + 来向FIN消息的最大生存时间(MSL)
。可以看到加起来正好是2MSL。等待2MSL,客户端就可以放心大胆的释放TCP连接了,此时可以使用该端口号连接任何服务器。
如果没有TIME_WAIT,新连接直接复用该连接占用的端口话,恰好回复的ACK包没有达到对端,导致对方重传FIN包,这时新连接就会被错误的关闭。
2.1.2 使用了连接池为什么还会出现大量的TIME_WAIT连接呢
首先大量的TIME_WAIT连接说明了我们的go程序建立了大量的连接然后又关闭了,但是理论上使用了连接池连接都应该得到复用,不会建立大量的连接才对。
这时我首先检查了是不是连接池的ConnMaxLifetime
和ConnMaxIdleTime
设置的太小导致连接被关闭。我回看了代码发现同事设置了一个小时的时长,那么就不可能是这个原因了。
然后我将怀疑的矛头指向了TDSQL,因为TDSQL是我们首次使用,之前使用Mysql时也没有遇到过这个问题,会不会是TDSQL发送/回复了某个特殊的包导致了客户端主动断开呢?
2.2 验证是否是TDSQL的问题
为了验证上述的猜想,使用tcpdump在服务器上抓了个包
tcpdump -i any host 10.43.0.43 -w output.pcap
然后将抓到的outout.pcap包down下来后丢到本机wireshark中进行分析,选择一个端口过滤下可以看到整个tcp连接的所有包。
可以看到TDSQL发送的都是正常的mysql协议包,并没有什么特殊的包,因此到这里基本可以确认不是TDSQL的锅。
那么排查的重点又回到了golang连接池,golang连接池为什么会主动断开连接?
2.3 golang为什么会主动断开连接?
由于golang整个sql包非常复杂,我们可以自底向上的思路来排查问题,首先我们找到mysql驱动包go-sql-driver/mysql
中关闭连接的函数:
func (mc *mysqlConn) Close() (err error)
它位于connection.go
文件中。
下面我们使用dlv 来启动上面的go程序
$ dlv debug main.go
进入到dlv控制台,然后在控制台中输入break mysql.(*mysqlConn).Close
在这个函数上打个断点,继续输入c
命令让程序继续执行,然后使用ab命令进行这个web程序进行压测。
不出所料程序断在了mysql.(*mysqlConn).Close。然后我们使用bt
命令来打印下调用栈:
可以清楚的看到整个核心调用链是:
rwos.Close -> driverConn.releaseConn -> DB.putConn -> driverConn.Close -> mysqlConn.Close
问题的关键是DB.putConn ,我们可以分析下源码:
func (db *DB) putConn(dc *driverConn, err error, resetSession bool) {
...
added := db.putConnDBLocked(dc, nil)
db.mu.Unlock()
if !added {
dc.Close()
return
}
}
func (db *DB) putConnDBLocked(dc *driverConn, err error) bool {
if db.closed {
return false
}
if db.maxOpen > 0 && db.numOpen > db.maxOpen {
return false
}
if c := len(db.connRequests); c > 0 {
var req chan connRequest
var reqKey uint64
for reqKey, req = range db.connRequests {
break
}
delete(db.connRequests, reqKey) // Remove from pending requests.
if err == nil {
dc.inUse = true
}
req <- connRequest{
conn: dc,
err: err,
}
return true
} else if err == nil && !db.closed {
if db.maxIdleConnsLocked() > len(db.freeConn) { // db.maxIdleConnsLocked()取自db.maxIdleCount
db.freeConn = append(db.freeConn, dc)
db.startCleanerLocked()
return true
}
db.maxIdleClosed++
}
return false
}
从源码中我们可以得知是DB.putConnDBLocked
返回了false
导致了连接关闭。为了验证这一点可以继续使用dlv 在dc.Close()
这一行打个断点,然后重新压测这个程序:
可以看到程序确实是走到了dc.Close()
这一行,我们继续打印上下文的数据:
到这里我们就知道了是由于db.maxIdleCount == len(db.freeConn)
导致了连接没有被复用。
db.maxIdleCount
是我们代码中设置的dbconnect.SetMaxIdleConns(5)
也就是5
那么问题的原因其实就很简单了,我们设置了最大闲置连接数为5,最大可建立连接数为10,那么进程中最多可出现10个连接,这10个连接中只有5个可以被丢回到连接池中复用,而另外5个连接由于超过了我们设置最大闲置连接数5所以不会被丢回到连接池中复用,因此使用完就close了。当并发高的情况下就会出现大量的连接打开与关闭。
3. 解决
最大闲置连接数设置成一个大于等于最大连接数的值即可,比如下面这样:
dbconnect.SetMaxIdleConns(10)
dbconnect.SetMaxOpenConns(10)