背景

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

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

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

開發(fā)同學一開始希望通過調整 MongoDB Java Driver 的超時參數(shù)來規(guī)避這個問題。
但經過詳細分析之后，這樣是無法根治問題的，而且超時配置應該如何調整也難以評估。

下面是關于對這個問題的分析、調優(yōu)的過程。

初步分析

從出錯的信息上看，是數(shù)據(jù)庫的操作響應超時了，此時客戶端配置的 SocketReadTimeout 為 60s。
那么，是什么操作會導致數(shù)據(jù)庫 60s 還沒能返回呢？

業(yè)務操作

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

分析服務是Java實現(xiàn)的一個應用程序，在每天凌晨1:00 會拉取出前一天修改的工單信息(要求按工單號排序)進行處理。

由于工單表非常大(千萬級)，所以在處理時會采用分頁的做法(每次取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)

第二次拉取，以第一次拉取的最后一條記錄的工單號作為起點

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})

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

為了精確的模擬該場景，我們在測試環(huá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")

輸出結果如下

"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條索引項！