背景

最近線上的一個工單分析服務一直不大穩定，監控平臺時不時發出數據庫操作超時的告警。

運維兄弟溝通后，發現在每天凌晨1點都會出現若干次的業務操作失敗，而數據庫監控上并沒有發現明顯的異常。

在該分析服務的日志中發現了某個數據庫操作產生了 SocketTimeoutException。

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

下面是關于對這個問題的分析、調優的過程。

初步分析

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

業務操作

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

分析服務是Java實現的一個應用程序，在每天凌晨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)..

根據這樣的查詢，開發人員給數據表使用的索引如下：

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

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

為了精確的模擬該場景，我們在測試環境中預置了小部分數據，對拉取記錄的SQL執行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,

在執行過程中發現，檢索1000條記錄，居然需要掃描 13.6 W條索引項！