背景

最近線(xiàn)上的一個(gè)工單分析服務(wù)一直不大穩(wěn)定，監(jiān)控平臺(tái)時(shí)不時(shí)發(fā)出數(shù)據(jù)庫(kù)操作超時(shí)的告警。

運(yùn)維兄弟溝通后，發(fā)現(xiàn)在每天凌晨1點(diǎn)都會(huì)出現(xiàn)若干次的業(yè)務(wù)操作失敗，而數(shù)據(jù)庫(kù)監(jiān)控上并沒(méi)有發(fā)現(xiàn)明顯的異常。

在該分析服務(wù)的日志中發(fā)現(xiàn)了某個(gè)數(shù)據(jù)庫(kù)操作產(chǎn)生了 SocketTimeoutException。

開(kāi)發(fā)同學(xué)一開(kāi)始希望通過(guò)調(diào)整 MongoDB Java Driver 的超時(shí)參數(shù)來(lái)規(guī)避這個(gè)問(wèn)題。
但經(jīng)過(guò)詳細(xì)分析之后，這樣是無(wú)法根治問(wèn)題的，而且超時(shí)配置應(yīng)該如何調(diào)整也難以評(píng)估。

下面是關(guān)于對(duì)這個(gè)問(wèn)題的分析、調(diào)優(yōu)的過(guò)程。

初步分析

從出錯(cuò)的信息上看，是數(shù)據(jù)庫(kù)的操作響應(yīng)超時(shí)了，此時(shí)客戶(hù)端配置的 SocketReadTimeout 為 60s。
那么，是什么操作會(huì)導(dǎo)致數(shù)據(jù)庫(kù) 60s 還沒(méi)能返回呢？

業(yè)務(wù)操作

左邊的數(shù)據(jù)庫(kù)是一個(gè)工單數(shù)據(jù)表(t_work_order)，其中記錄了每張工單的信息，包括工單編號(hào)(oid)、最后修改時(shí)間(lastModifiedTime)

分析服務(wù)是Java實(shí)現(xiàn)的一個(gè)應(yīng)用程序，在每天凌晨1:00 會(huì)拉取出前一天修改的工單信息(要求按工單號(hào)排序)進(jìn)行處理。

由于工單表非常大(千萬(wàn)級(jí))，所以在處理時(shí)會(huì)采用分頁(yè)的做法(每次取1000條)，使用按工單號(hào)翻頁(yè)的方式：

第一次拉取

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)

第二次拉取，以第一次拉取的最后一條記錄的工單號(hào)作為起點(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ù)這樣的查詢(xún)，開(kāi)發(fā)人員給數(shù)據(jù)表使用的索引如下：

db.t_work_order.ensureIndexes({  "oid" : 1,  "lastModifiedTime" : -1})

盡管該索引與查詢(xún)字段基本是匹配的，但在實(shí)際執(zhí)行時(shí)卻表現(xiàn)出很低的效率：
第一次拉取時(shí)間非常的長(zhǎng)，經(jīng)常超過(guò)60s導(dǎo)致報(bào)錯(cuò)，而后面的拉取時(shí)間則會(huì)快一些

為了精確的模擬該場(chǎng)景，我們?cè)跍y(cè)試環(huán)境中預(yù)置了小部分?jǐn)?shù)據(jù)，對(duì)拉取記錄的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í)行過(guò)程中發(fā)現(xiàn)，檢索1000條記錄，居然需要掃描 13.6 W條索引項(xiàng)！