僅378條數據居然導致合服失敗?!

  • 2020 年 2 月 14 日
  • 筆記

| 作者:伍旭飛,騰訊雲數據庫高級工程師,主要負責騰訊雲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幾個服全部回檔測試了一把,最終測試成功!

往期推薦

(點擊圖片即可跳轉閱讀)

開年大禮包 

↓↓更多驚喜優惠請點這兒~