背景

最近線上的一個(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í)客戶端配置的 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ù)這樣的查詢，開(kāi)發(fā)人員給數(shù)據(jù)表使用的索引如下：

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

盡管該索引與查詢字段基本是匹配的，但在實(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)！

其中，幾乎所有的開(kāi)銷(xiāo)都花費(fèi)在了 一個(gè)seeks操作上了。

索引seeks的原因

官方文檔對(duì)于 seeks 的解釋如下：

The number of times that we had to seek the index cursor to a new position in order to complete the index scan.

翻譯過(guò)來(lái)就是：

seeks 是指為了完成索引掃描(stage)，執(zhí)行器必須將游標(biāo)定位到新位置的次數(shù)。

我們都知道 MongoDB 的索引是B+樹(shù)的實(shí)現(xiàn)(3.x以上)，對(duì)于連續(xù)的葉子節(jié)點(diǎn)掃描來(lái)說(shuō)是非常快的(只需要一次尋址)，那么seeks操作太多則表示整個(gè)掃描過(guò)程中出現(xiàn)了大量的尋址(跳過(guò)非目標(biāo)節(jié)點(diǎn))。
而且，這個(gè)seeks指標(biāo)是在3.4版本支持的，因此可以推測(cè)該操作對(duì)性能是存在影響的。

為了探究 seeks 是怎么產(chǎn)生的，我們對(duì)查詢語(yǔ)句嘗試做了一些變更：

去掉 exists 條件

exists 條件的存在是因?yàn)闅v史問(wèn)題(一些舊記錄并不包含工單號(hào)的字段)，為了檢查exists查詢是否為關(guān)鍵問(wè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")}
  })
  .sort({"oid":1}).limit(1000)
  .explain("executionStats")

執(zhí)行后的結(jié)果為：

"nReturned" : 1000,
"executionTimeMillis" : 1533,
"totalKeysExamined" : 272322,
"totalDocsExamined" : 272322,
 
...

"inputStage" : {
  "stage" : "FETCH",
  "filter" : {
      "$and" : [
          {
              "lastModifiedTime" : {
                  "$lt" : ISODate("2019-04-09T10:44:57.106Z")
              }
          },
          {
              "lastModifiedTime" : {
                  "$gt" : ISODate("2019-04-09T09:44:57.106Z")
              }
          }
      ]
},

...

"indexBounds" : {
    "oid" : [
        "[MinKey, MaxKey]"
    ],
    "lastModifiedTime" : [
        "[MaxKey, MinKey]"
    ]
},
"keysExamined" : 272322,
"seeks" : 1,

這里發(fā)現(xiàn)，去掉 exists 之后，seeks 變成了1次，但整個(gè)查詢掃描了 27.2W 條索引項(xiàng)！ 剛好是去掉之前的2倍。

seeks 變?yōu)?次說(shuō)明已經(jīng)使用了葉節(jié)點(diǎn)順序掃描的方式，然而由于掃描范圍非常大，為了找到目標(biāo)記錄，會(huì)執(zhí)行順序掃描并過(guò)濾大量不符合條件的記錄。

在 FETCH 階段出現(xiàn)了 filter可說(shuō)明這一點(diǎn)。與此同時(shí)，我們檢查了數(shù)據(jù)表的特征：同一個(gè)工單號(hào)是存在兩條記錄的！于是可以說(shuō)明：

在存在exists查詢條件時(shí)，執(zhí)行器會(huì)選擇按工單號(hào)進(jìn)行seeks跳躍式檢索，如下圖：

在不存在exists條件的情況下，執(zhí)行器選擇了葉節(jié)點(diǎn)順序掃描的方式，如下圖：

gt 條件和反序

除了第一次查詢之外，我們對(duì)后續(xù)的分頁(yè)查詢也進(jì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)
  .explain("executionStats")

上面的語(yǔ)句中，主要是增加了$gt: "VXZ190"這一個(gè)條件，執(zhí)行過(guò)程如下：

"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1004,
"totalDocsExamined" : 1000,

...

"indexBounds" : {
  "oid" : [ 
    "(\"VXZ190\", {})"
  ],
  "lastModifiedTime" : [ 
    "(new Date(1554806697106), new Date(1554803097106))"
  ]
},
"keysExamined" : 1004,
"seeks" : 5,

可以發(fā)現(xiàn)，seeks的數(shù)量非常少，而且檢索過(guò)程只掃描了1004條記錄，效率是很高的。

那么，是不是意味著在后面的數(shù)據(jù)中，滿足查詢的條件的記錄非常密集呢？

為了驗(yàn)證這一點(diǎn)，我們將一開(kāi)始第一次分頁(yè)的查詢做一下調(diào)整，改為按工單號(hào)降序的方式(從后往前掃描):

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

新的"反序查詢語(yǔ)句"的執(zhí)行過(guò)程如下：

"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1001,
"totalDocsExamined" : 1000,

...

"direction" : "backward",
"indexBounds" : {
  "oid" : [ 
    "[MaxKey, MinKey]"
  ],
  "lastModifiedTime" : [ 
    "(new Date(1554803097106), new Date(1554806697106))"
  ]
},
"keysExamined" : 1001,
"seeks" : 2,

可以看到，執(zhí)行的效率更高了，幾乎不需要什么 seeks 操作！

經(jīng)過(guò)一番確認(rèn)后，我們獲知了在所有數(shù)據(jù)的分布中，工單號(hào)越大的記錄其更新時(shí)間值也越大，基本上我們想查詢的目標(biāo)數(shù)據(jù)都集中在尾端。

于是就會(huì)出現(xiàn)一開(kāi)始提到的，第一次查詢非常慢甚至超時(shí)，而后面的查詢就快了。

上面提到的兩個(gè)查詢執(zhí)行路線如圖所示：

加入$gt 條件，從中間開(kāi)始檢索

反序，從后面開(kāi)始檢索

優(yōu)化思路

通過(guò)分析，我們知道了問(wèn)題的癥結(jié)在于索引的掃描范圍過(guò)大，那么如何優(yōu)化，以避免掃描大量記錄呢？

從現(xiàn)有的索引及條件來(lái)看，由于同時(shí)存在gt、exists以及葉子節(jié)點(diǎn)的時(shí)間范圍限定，不可避免的會(huì)產(chǎn)生seeks操作，
而且查詢的性能是不穩(wěn)定的，跟數(shù)據(jù)分布、具體查詢條件都有很大的關(guān)系。

于是一開(kāi)始所提到的僅僅是增加 socketTimeout 的閾值可能只是治標(biāo)不治本，一旦數(shù)據(jù)的索引值分布變化或者數(shù)據(jù)量持續(xù)增大，可能會(huì)發(fā)生更嚴(yán)重的事情。

回到一開(kāi)始的需求場(chǎng)景，定時(shí)器要求讀取每天更新的工單(按工單號(hào)排序)，再進(jìn)行分批處理。

那么，按照化零為整的思路，新增一個(gè)lastModifiedDay字段，這個(gè)存儲(chǔ)的就是lastModifiedTime對(duì)應(yīng)的日期值(低位取整)，這樣在同一天內(nèi)更新的工單記錄都有同樣的值。

建立組合索引 {lastModifiedDay:1, oid:1}，相應(yīng)的查詢條件改為：

{
 "lastModifiedDay": new Date("2019-04-09 00:00:00.000")，
 "oid": {$gt: "VXZ190"}
} 
-- limit 1000

執(zhí)行結(jié)果如下：

"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1000,
"totalDocsExamined" : 1000,

...

"indexBounds" : {
    "lastModifiedDay" : [
        "(new Date(1554803000000), new Date(1554803000000))"
    ],
    "oid" : [
        "(\"VXZ190\", {})"
    ]
},
"keysExamined" : 1000,
"seeks" : 1,

這樣優(yōu)化之后，每次查詢最多只掃描1000條記錄，查詢速度是非常快的！

小結(jié)

本質(zhì)上，這就是一種空間換時(shí)間的方法，即通過(guò)存儲(chǔ)一個(gè)額外的索引字段來(lái)加速查詢，通過(guò)增加少量的存儲(chǔ)開(kāi)銷(xiāo)提升了整體的效能。

在對(duì)于許多問(wèn)題進(jìn)行優(yōu)化時(shí)，經(jīng)常是需要從應(yīng)用場(chǎng)景觸發(fā)，適當(dāng)?shù)霓D(zhuǎn)換思路。

比如在本文的問(wèn)題中，是不是一定要增加字段呢？如果業(yè)務(wù)上可以接受不按工單號(hào)排序進(jìn)行讀取，那么僅使用更新時(shí)間字段進(jìn)行分頁(yè)拉取也是可以達(dá)到效果的，具體還是要由業(yè)務(wù)場(chǎng)景來(lái)定。

總結(jié)

以上就是這篇文章的全部?jī)?nèi)容了，希望本文的內(nèi)容對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值，謝謝大家對(duì)腳本之家的支持。