golang使用mongodb驱动mgo异常崩溃问题

golang mongodb 游戏开发 mgo 18-05-15 21:49 2228  

背景 在我的后端游戏架构中,有一个golang开发的数据服务器,用来存储落地玩家的历史数据,并提供给客户端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() //------1603行 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(): // Cannot do this because it lacks timeout support. :-( //conn, err = net.DialTCP("tcp", nil, server.tcpaddr) 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) //------------------- add log 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的设置函数说明也有提到: // SetPoolLimit sets the maximum number of sockets in use in a single server // before this session will block waiting for a socket to be available. // The default limit is 4096. // // This limit must be set to cover more than any expected workload of the // application. It is a bad practice and an unsupported use case to use the // database driver to define the concurrency limit of an application. Prevent // such concurrency "at the door" instead, by properly restricting the amount // of used resources and number of goroutines before they are created. 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() //----------------位置1 abended = server.abended if server.closed { server.Unlock() return nil, abended, errServerClosed } n := len(server.unusedSockets) if poolLimit > 0 && len(server.liveSockets)-n >= poolLimit { //------------------- 位置2 server.Unlock() return nil, false, errPoolLimit } if n > 0 { socket = server.unusedSockets[n-1] server.unusedSockets[n-1] = nil // Help GC. server.unusedSockets = server.unusedSockets[:n-1] info := server.info server.Unlock() err = socket.InitialAcquire(info, timeout) if err != nil { continue } } else { server.Unlock() //----------------------- 位置3 socket, err = server.Connect(timeout) if err == nil { server.Lock() //----------------------- 位置4 // We've waited for the Connect, see if we got // closed in the meantime if server.closed { server.Unlock() socket.Release() socket.Close() return nil, abended, errServerClosed } server.liveSockets = append(server.liveSockets, socket) //------------------位置5 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找不到等)

KelUrgeld 2019-09-03 06:35

Muscle Propecia Finasteride Alli Tabs Keflex And Yeast Infection <a href=http://rxbill6.com>levitra shipped from us</a> Aciphex Cialis Receta Europa

LesTentee 2019-08-28 12:59

Lisinopril Purchase Online Vardenafil Online No Prescription <a href=http://viacheap.com>viagra online prescription</a> Jenerik Priligy

Ellextemi 2019-04-08 11:21

Amoxicillin Rash Pictures Prix Cialis France Pharmacie Buy Propecia Online 20mg <a href=http://hxdrugs.com>cialis 5mg best price</a> Cephalexin Dogs Side Effects Comprar Cialis Por Transferencia Bancaria Generique Baclofen En France

MatKami 2019-03-24 05:10

Cialis Marche Pas Cialis Como Tomar <a href=http://oc-35.com>buy propecia without doctor</a> Johnson And Johnsontretinoin A .05 Keflex And Constipation Purchase Female Viagra Online

LesTentee 2019-03-06 12:56

Order Kamagra Zithromax Discount Card <a href=http://leviinusa.com>levitra online no prescription</a> Vente Kamagra Espagne

Ellextemi 2019-03-03 16:03

Orlistat Achat Ligne Dapoxetina Compresse Cialis Dove Acquistarlo Forum <a href=http://antabusefast.com>is disulfiram approved in canada</a> Side Effects Old Cephalexin Come Posso Comprare Il Viagra Valtrex Coupons Online Lowpricenonprescriptionviagra

stone 2018-06-19 11:58

@liao 可以看看压测时和mongodb的链接数有多少?mongdb是一个独立机器吧?另外可以统计下qps。查询语句也可以变化比较一下,你原始的语句里面有很多比较和排序的,只查某个固定key呢?另外你的test耗时线性增加,这个很重要,要么程序自己耗时更多,要么mgo返回慢了,可以看是否能够把耗时统计更细化后定位?

@stone 2018-06-19 09:53

压测的时候 如果跑100个的话一个核都没用完,如果跑10000个的话用了2个多核

@stone 2018-06-19 09:50

您好 cpu是四核,我开100个routine进行测试的时候消耗的时间就开始明显增加,内存也是足够用的,讲道理机器性能不是瓶颈,但是mgo又感觉没啥可优化的。我看routine监控有不少在decode,然后我把语句改为求count,但是问题依然存在。现在确实没啥思路了

stone 2018-06-18 16:00

@liao 不知道你测试机器的CPU是几核的,如果你开太多routine,每个routine的测试量又很大,会不会自己的压测端就已经切换吃不消了?可以看看压测时的机器性能指标。

liao 2018-06-18 11:27

您好回复的代码没有显示格式抱歉了,大概问题就是当创建很多的协程压测时【go test()】耗时线性增加,查看mongo日志没有发现慢查询,如果用普通的循环调用test()时耗时很稳定【40毫秒左右吧】

liao 2018-06-18 11:23

您好博主,我这几天在使用mgo驱动查询mongo时发现做并发压测时耗时线性增加,您能提供一下思路吗 func main() { runtime.GOMAXPROCS(0) for i:=0;i<100;i++ { go test() } time.Sleep(1000*time.Second) } func test(){ t1 := time.Now().UnixNano() / 1e6 session:=CloneSession() defer session.Close() c:=session.DB("irectoryperdb").C("test") err:=c.Find(bson.M{"data.id": bson.M{"$gte": 1527319500, "$lte": 1527319500}, "index": "test_1min_index"}).Select(bson.M{"data.id":1}).Sort("-data.id").All(&kline) if err!=nil{ fmt.Println(err) } fmt.Printf("%d,%d\n",time.Now().UnixNano()/1e6 - t1,len(kline)) }