僅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幾個服全部回檔測試了一把,最終測試成功!
往期推薦
(點擊圖片即可跳轉閱讀)
開年大禮包
↓↓更多驚喜優惠請點這兒~