仅378条数据居然导致合服失败?!

| 作者:伍旭飞,腾讯云数据库高级工程师,主要负责腾讯云Redis、MongoDB开发。


故事从一个MongoDB数据库连接超时案例说起。该异常导致2次合服失败,前面已在服务器上抓包并dump下来,下方是客户端超时现场截图:

从截图不难看出,这是一个Nodejs服务出错信息,推测DBA应该是用的nodejs mongodb来实现连接数据库并进行操作,找到这个driver的官网https://github.com/mongodb/node-mongodb-native,clone了一份代码下来。简单看了下,再结合上图,初步分析出错连接是在第38个连接超时的。

1. 分析抓包内容

由于前面已经在出错服务器上抓包了,因此,首先我用wireShark打开从服务器上dump下来的文件,wireShark很智能,能分析多种常用协议,很方便,但是也容易带来误判。比如我们的数据库连接很多地方都被误判为X11协议:

一开始很纠结这个错误,其实这当然不是什么x11协议,只是碰巧模式匹配上了,到wireShark设置了下,取消了X11的分析,很容易从端口和连接看出,就是数据库连接。

仔细检查了抓包内容,大致如下:

(1)开始有个连接从数据库拉取了大概3M多的数据。

(2)后面陆续有常规的三次握手连接建立成功,但是都基本没有实质性的数据传输,就走了正常的tcp结束流程了。

(3)从抓包内容来看,服务器不存在未回应客户端syn连接包的情况。

好了,到这里分析的内容,似乎完全解释不了为什么会超时,那么下一步就是和用户沟通,获取更多的信息了。

(4)所有的tcp链接均为客户端发起FIN主动关闭,不存在服务器主动关闭客户端连接的情况。

2. 出错代码

通过沟通,拿到了出错部分工具的代码片段(最开始没有完整的函数,后面才拿到完整函数):

function merge_union_info(dbs) {    var union_data = [];      async.each(        dbs,        function(path, cb) {            mongodb.connect(path, (err, db) => {                if (err) {                    cb(err);                    return                }                  db.collection('union').find().sort({level: -1, exp: -1}).toArray((err1, v) => {                    if (err1) {                        db.close();                        console.log(err1);                        return                    }                      let loop = v.length > 50 ? 50 : v.length;                    let u_data = [];                    for (let i = 0; i < loop; i++) {                        v[i].merge_flag = 1;                        u_data.push(v[i]);                    }                      union_data.push(u_data);                      db.close();                    cb();                });            })        },        function(err) {            if (err) {                console.log("[ERROR]merge union-data failed !!!");                return            }              async.waterfall([                function(cb1) {                    mongodb.connect(dbs[0], (err1, db) => {                        if (err1) {                            cb1(`[ERROR]gen union-data [drop] failed for ${err1}`)                            return                        }                          var col = db.collection('union');                        db.collection('union').drop((err2, r2) => {                            db.close();                            cb1(err2);                        });                    });                 },                function(cb1) {                    async.each(                        union_data,                         function(u_data, cb2) {                            mongodb.connect(dbs[0], (err1, db) => {                                if (err1) {                                    cb2(`[ERROR]gen union-data [insert] failed for ${err1}`)                                    return                                }                                  var col = db.collection('union');                                col.insertMany(u_data, (err2, r2) => {                                    db.close();                                    cb2(err2);                                });                            });                         },                        function(errN) {                            cb1(errN);                        }                    );                },            ], function(errX, r) {                if (errX) {                    console.log("[ERROR]gen union-data failed for ", errX);                }else {                    console.log("4 - update union-data ok !!!");                }            });        }    );}

熟悉nodejs的都知道,nodejs的优点是无同步操作,所以性能相对高。所以通过代码分析,第一反应是数据量太大导致建立了太多的tcp连接,而mongodb是每用户一个线程的处理模型,极有可能造成tcp连接达到max open file数量或者线程太多,导致整个系统性能下降,以至于无回应。

3. 尝试重现

通过代码分析,我简单写了个函数,希望能重现,mongodb用的是虚拟机上自己搭建,代码如下:

function doLoopInsertTest(mongourl:string){    for(var i = 0; i < maxInsertCount/500; i++){                mongodb.MongoClient.connect(mongourl, function(err, client) {            if (err != null){                console.log("error:", err, "n")                return            }                                console.log("Connected successfully to server");            const db = client.db("testdb");            db.collection("testfei").insertMany(getNewDoc(i*500), (err, result:mongodb.InsertWriteOpResult)=>{                if (err != null){                    console.log("write error:", err)                    return                }            })                    })    }}

这里模拟了用户是每500个合并插入的代码,在自建的mongodb上,很快就超过了1024的max fd限制。unlimit修改后,重启mongodb进程,再次测试,很快客户端这边无响应,但是出错信息和用户不完全相同,尝试了好几次,其中有一次出现了timeout的错误信息。

4. 用户反馈

似乎大功告成,于是第二天把相关信息和用户沟通,用户反馈出错的部分没有那么多数据,而且总共就插入了100条数据,并提供了要合并的2个表的数据。

我在测试环境mongodbrestore看了下,一个表示257条,一个表示121条,总共加起来378条数据!!这根本不可能出错,就算是每个插入建立一个连接,也不会出错。

出于谨慎的考虑,我还是写了个小代码片段,在本地的虚拟机环境下测试了下,当然是完全没问题。万一是真的云服务器独有的问题呢,我申请了一个测试的mongodb,把数据导入,然后用nodejs代码测试了下,依然没有任何问题!

于是,与用户进一步沟通,是否是mongodb driver代码版本不够新?

得到反馈是:mongodb driver代码确实不够新,但是,他们前几次合服也是这个代码,都能成功。用户不认为代码有问题,也不认可是库的版本问题。

用户也不适合用我提供的代码直接测试,因为每次测试都要发公告停服合服,合服失败后,部分数据要手工回档,风险太大。

5. 柳暗花明

似乎陷入了死胡同,我们不相信300多条数据插入会有问题,用户不认同我们的结论,我甚至询问用户,有没有可能真的ip和端口写错了(其实也说不同,错误日志里的端口是对的)。

这个时候,突然想起来,合服不可能只合并工会(前面的代码是工会合并的部分),前面应该还有角色这些合并吧。用户确认了,发了代码截图:

并且标注了出错代码是update_union_info。

这里就比较明显能看出问题了:数据量最大的是update_user_info,而基于nodejs的特点,update_user_info应该也是异步操作的,也就是说,执行到update_union_info的时候,update_user_info一定是没有执行完毕的!而nodejs是单线程!!! 单线程!!! 单线程!!!重要的事情3遍。

所以,假如update_user_info的运算量非常大,那么,即使网络层tcp连接成功,也极有可能得不到运行机会,等到cpu释放出来,很可能已经超时了。

6. 再次尝试重现

通过前面的分析,写了简单粗暴代码来重现:

这个代码很粗暴,setTimeout模拟的是用户合并角色数据的过程,假设运行了50S。

很快我们的超时断点命中了:

把这个分析结果和用户反馈后,用户同意改代码,但是想提前测试下。

7. 问题解决

正好我们mongodb回档功能会提供一个临时实例,回档过程对线上完全无影响,是不是很神奇~

创建出来的临时实例可以选择替换线上的实例,也可以选择不替换,转正为一个临时实例(保存2天)。2天足够用户测试了,用户修改代码为全部串行后,将20几个服全部回档测试了一把,最终测试成功!

往期推荐

(点击图片即可跳转阅读)

开年大礼包 

↓↓更多惊喜优惠请点这儿~