背景
最近線上的一個工單分析服務(wù)一直不大穩(wěn)定,監(jiān)控平臺時(shí)不時(shí)發(fā)出數(shù)據(jù)庫操作超時(shí)的告警。
運(yùn)維兄弟溝通后,發(fā)現(xiàn)在每天凌晨1點(diǎn)都會出現(xiàn)若干次的業(yè)務(wù)操作失敗,而數(shù)據(jù)庫監(jiān)控上并沒有發(fā)現(xiàn)明顯的異常。
在該分析服務(wù)的日志中發(fā)現(xiàn)了某個數(shù)據(jù)庫操作產(chǎn)生了 SocketTimeoutException。
開發(fā)同學(xué)一開始希望通過調(diào)整 MongoDB Java Driver 的超時(shí)參數(shù)來規(guī)避這個問題。
但經(jīng)過詳細(xì)分析之后,這樣是無法根治問題的,而且超時(shí)配置應(yīng)該如何調(diào)整也難以評估。
下面是關(guān)于對這個問題的分析、調(diào)優(yōu)的過程。
初步分析
從出錯的信息上看,是數(shù)據(jù)庫的操作響應(yīng)超時(shí)了,此時(shí)客戶端配置的 SocketReadTimeout 為 60s。
那么,是什么操作會導(dǎo)致數(shù)據(jù)庫 60s 還沒能返回呢?
業(yè)務(wù)操作

左邊的數(shù)據(jù)庫是一個工單數(shù)據(jù)表(t_work_order),其中記錄了每張工單的信息,包括工單編號(oid)、最后修改時(shí)間(lastModifiedTime)
分析服務(wù)是Java實(shí)現(xiàn)的一個應(yīng)用程序,在每天凌晨1:00 會拉取出前一天修改的工單信息(要求按工單號排序)進(jìn)行處理。
由于工單表非常大(千萬級),所以在處理時(shí)會采用分頁的做法(每次取1000條),使用按工單號翻頁的方式:
第一次拉取
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")}, "oid": {$exists: true}}) .sort({"oid":1}).limit(1000)第二次拉取,以第一次拉取的最后一條記錄的工單號作為起點(diǎn)
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")}, "oid": {$exists: true, $gt: "VXZ190"}}) .sort({"oid":1}).limit(1000)..根據(jù)這樣的查詢,開發(fā)人員給數(shù)據(jù)表使用的索引如下:
db.t_work_order.ensureIndexes({ "oid" : 1, "lastModifiedTime" : -1})盡管該索引與查詢字段基本是匹配的,但在實(shí)際執(zhí)行時(shí)卻表現(xiàn)出很低的效率:
第一次拉取時(shí)間非常的長,經(jīng)常超過60s導(dǎo)致報(bào)錯,而后面的拉取時(shí)間則會快一些
為了精確的模擬該場景,我們在測試環(huán)境中預(yù)置了小部分?jǐn)?shù)據(jù),對拉取記錄的SQL執(zhí)行Explain:
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")} "oid": {$exists: true}}) .sort({"oid":1}).limit(1000) .explain("executionStats")輸出結(jié)果如下
"nReturned" : 1000,
"executionTimeMillis" : 589,
"totalKeysExamined" : 136661,
"totalDocsExamined" : 1000,...
"indexBounds" : {
"oid" : [
"[MinKey, MaxKey]"
],
"lastModifiedTime" : [
"(new Date(1554806697106), new Date(1554803097106))"
]
},
"keysExamined" : 136661,
"seeks" : 135662,
在執(zhí)行過程中發(fā)現(xiàn),檢索1000條記錄,居然需要掃描 13.6 W條索引項(xiàng)!
新聞熱點(diǎn)
疑難解答
圖片精選