背景
在我的后端游戏架构中,有一个golang开发的数据服务器dataserver,用来存储落地玩家的历史数据,并提供给客户端http接口查询。由于之前的项目已经在使用mongodb,出于方便易用支持类json格式的bson类型,且mongodb3.0以后引入了高效的WiredTiger引擎,因此该数据服务也直接使用mongodb作为落地存储和缓存。
mongodb官方提供了各种语言的驱动,但是并没提供官方驱动,业界用的较多的是社区开源的mgo方案,我也顺理成章采用了mgo库访问mongodb。
问题显现
开发和测试过程比较顺畅,上线初期也一直比较稳定。后来因为业务发展,用户量上了一个台阶后,该dataserver若干天不定时会崩溃。奔溃的地点也很诡异:
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x6ed322]
goroutine 23 [running]:
.../vendor/gopkg.in/mgo%2ev2.(*Session).Clone(0x0, 0xc420173358)
............../vendor/gopkg.in/mgo.v2/session.go:1603 +0x22
.../db.GetNewSession(0xa1faff, 0xc, 0xed27f8717, 0x104)
mgo源码中对应如下:
func (s *Session) Clone() *Session {
s.m.Lock()
scopy := copySession(s, true)
s.m.Unlock()
return scopy
}
在Session的Clone接口中的加锁的地方崩溃,这里的session是启动的时候就初始化好的,且锁m也是初始化好的,这个地方不应该崩溃的。从panic提示来看应该是session或者m为空或者坏掉了。
问题追踪
因为在测试环境和上线初期都很稳定,估计是在大请求量的情况才有几率触发。为了定位问题,专门协议了针对性的压力测试工具反复调用dataserver暴露的http接口。多次反复持续测试以后发现,确实可以在测试环境触发这个异常。
查看到mongodb的日志后,发现一个连接被拒绝的异常日志,日志显示dataserver和mongodb的打开连接数已经达到了上限2w, 而在达到2w的时间点和dataserver崩溃时间比较吻合,猜测有一定联系。上限是2w的原因是在mongo.conf中配置了最大连接数2w。
mongodb异常日志如下:
I NETWORK [initandlisten] connection refused because too many open connections: 20000
而且从mongo.log中发现打开连接数一直是处于持续增加的状态,而从netstat看到确实有这么多连接处于ESTABLISH状态。
mgo驱动中是有一个自己维护的socket链接池,之前没有显示设置,一直采用mgo的默认值4096。虽然mgo也说了连接池的限制不是一个硬限制,会有误差,但是也不至于超过4096达到2w还在增加吧。为了发现大大超过限制的链接是怎么建立起来的,在mgo的源码中建立链接的地方增加了日志 server.go:
func (server *mongoServer) Connect(timeout time.Duration) (*mongoSocket, error) {
server.RLock()
master := server.info.Master
dial := server.dial
server.RUnlock()
logf("Establishing new connection to %s (timeout=%s)...", server.Addr, timeout)
var conn net.Conn
var err error
switch {
case !dial.isSet():
conn, err = net.DialTimeout("tcp", server.ResolvedAddr, timeout)
if tcpconn, ok := conn.(*net.TCPConn); ok {
tcpconn.SetKeepAlive(true)
} else if err == nil {
panic("internal error: obtained TCP connection is not a *net.TCPConn!?")
}
case dial.old != nil:
conn, err = dial.old(server.tcpaddr)
case dial.new != nil:
conn, err = dial.new(&ServerAddr{server.Addr, server.tcpaddr})
default:
panic("dialer is set, but both dial.old and dial.new are nil")
}
if err != nil {
logf("Connection to %s failed: %v", server.Addr, err.Error())
return nil, err
}
logf("Connection to %s established.", server.Addr)
logger.Info("new conn with server:%p", server)
stats.conn(+1, master)
return newSocket(server, conn, timeout), nil
}
调用SetPoolLimit设置链接池200,并增加日志后,重新做版压测。发现链接池的限制并没有生效,运行久了之后,链接数还是达到了2w之巨。从新加日志可以发现所有链接都是dataserver建立起来,并没有其他程序和mongodb建立链接。
问题发现
后来从新加的日志,发现了新的线索,就是建立链接的server地址,中间有变化过。这个变化除非是mgo的session发生变化,后来发现了dataserver在操作mongodb出错的情况下,为了容错有一个重新初始化session的过程:
err := coll.Update(col, change)
if err != nil {
logger.Info("error update room record failed:%v room data:%+v", err, r)
err = ReInit()
if err != nil {
logger.Info("error reinit failed:%v", err)
return err
} else {
err = coll.Update(col, change)
}
}
mongodb初始化代码:
func ReInit() error {
logger.Info("re init mongo")
if m_session != nil{
m_session.Close()
}
return InitMongo()
}
func InitMongo() error {
var err error
m_session, err = mgo.Dial(conf.GetMongoAddrConf())
if err != nil {
return err
}
return nil
}
问题就在这里,操作mgo报错后,直接ReInit,重建了m_session,而之前的session并没有释放,导致老的session创建的socket链接一直得不到释放。所以每次发生错误重新初始化之后,都会导致重建一批socket,不断累积,直到达到mongodb的2w上限报错。
问题解决
问题定位之后,要解决就比较容易了,在ReInit之前对m_session做关闭释放动作,释放掉之前socket链接即可:
func ReInit() error {
logger.Info("re init mongo")
if m_session != nil{
m_session.Close()
}
return InitMongo()
}
mgo socket连接池
在定位这个问题的过程中,阅读了mgo库socket连接池相关代码,也看了一些网友的分析。其中提到一点比较有意思,就是连接池的上限设置并不是硬限制,即使设置了也可能超过的,mgo的设置函数说明也有提到:
func (s *Session) SetPoolLimit(limit int) {
s.m.Lock()
s.poolLimit = limit
s.m.Unlock()
}
连接池的限制默认是4096,同时不能用来作为应用层的并发控制,推荐应用层在接收请求后调用mgo库的时候就做好并发数控制。分析mgo源码后,可以看清楚poolLimit不能精确控制socket链接数。
server.AcquireSocket是需要和mongodb交互时,从底层拿一个socket,如果没有现成可用的socket,就新建一个connection。
func (server *mongoServer) AcquireSocket(poolLimit int, timeout time.Duration) (socket *mongoSocket, abended bool, err error) {
for {
server.Lock()
abended = server.abended
if server.closed {
server.Unlock()
return nil, abended, errServerClosed
}
n := len(server.unusedSockets)
if poolLimit > 0 && len(server.liveSockets)-n >= poolLimit {
server.Unlock()
return nil, false, errPoolLimit
}
if n > 0 {
socket = server.unusedSockets[n-1]
server.unusedSockets[n-1] = nil
server.unusedSockets = server.unusedSockets[:n-1]
info := server.info
server.Unlock()
err = socket.InitialAcquire(info, timeout)
if err != nil {
continue
}
} else {
server.Unlock()
socket, err = server.Connect(timeout)
if err == nil {
server.Lock()
if server.closed {
server.Unlock()
socket.Release()
socket.Close()
return nil, abended, errServerClosed
}
server.liveSockets = append(server.liveSockets, socket)
server.Unlock()
}
}
return
}
panic("unreachable")
}
从上面标记的4个位置可以看出,虽然每次获取一个连接前都会加锁(位置1),但是在高并发的情况下,多个routine同时调用AcquireSocket。如果n==0的情况,在位置3解锁了server并发起向mongodb的链接,在链接未成功还未到达位置4的时间窗口内,其他获取到server锁的routine也会检测到n==0而发起新链接,从而出现实际建立的链接数会比限制数大的情况,但是理论上不会大太多。从压力测试情况来看,设置200限制的情况,最终建立成功的连接数可以达到250左右。
总结和优化方向
以上记录了问题从发现到解决的全部过程,本质就是应用层代码bug导致mgo socket连接池链接泄漏,增加一行释放代码即可解决。不过整个问题的追踪过程还是颇有意义,做了一些总结和记录。
dataserver本身也需要继续做优化提高性能,优化方向大概包括以下:
- mongodb集群部署,读写分离(对的,现在还是单点部署)
- mgo连接池上限设置,还是需要设置一个合理只以免触发mongodb上限
- dataserver应用层预创建routine 控制并发数
- dataserver操作mgo失败即重新初始化session,这个机制要重新考虑,至少需要对操作错误的类型做细化,并发mongodb系统错误的可以不用重新初始化(比如查询的key找不到等)
- 虽然mongodb会尽力使用内存以提高访问效率,但是数据的查询和序列化始终需要额外的时间消耗,需要考虑在dataserver内不能再做一层缓存提高提高效率