目錄
- 背景
- 初步分析
- 索引seeks的原因
- 去掉 exists 條件
- gt 條件和反序
- 優化思路
- 小結
宣告：本文同步發表于 MongoDB 中文社區，傳送門：
http://www.mongoing.com/archives/27310
背景
最近線上的一個工單分析服務一直不大穩定，監控平臺時不時發出資料庫操作超時的告警，
運維兄弟溝通后，發現在每天凌晨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條索引項！
其中，幾乎所有的開銷都花費在了 一個seeks操作上了，
索引seeks的原因
官方檔案對于 seeks 的解釋如下：
The number of times that we had to seek the index cursor to a new position in order to complete the index scan.
翻譯過來就是：
seeks 是指為了完成索引掃描(stage)，執行器必須將游標定位到新位置的次數，
我們都知道 MongoDB 的索引是B+樹的實作(3.x以上)，對于連續的葉子節點掃描來說是非常快的(只需要一次尋址)，那么seeks操作太多則表示整個掃描程序中出現了大量的尋址(跳過非目標節點)，
而且，這個seeks指標是在3.4版本支持的，因此可以推測該操作對性能是存在影響的，
為了探究 seeks 是怎么產生的，我們對查詢陳述句嘗試做了一些變更：
去掉 exists 條件
exists 條件的存在是因為歷史問題(一些舊記錄并不包含工單號的欄位)，為了檢查exists查詢是否為關鍵問題，修改如下：
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")
執行后的結果為：
"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,
這里發現，去掉 exists 之后，seeks 變成了1次，但整個查詢掃描了 27.2W 條索引項！ 剛好是去掉之前的2倍，
seeks 變為1次說明已經使用了葉節點順序掃描的方式，然而由于掃描范圍非常大，為了找到目標記錄，會執行順序掃描并過濾大量不符合條件的記錄，
在 FETCH 階段出現了 filter可說明這一點，與此同時，我們檢查了資料表的特征：同一個工單號是存在兩條記錄的！于是可以說明：
- 在存在exists查詢條件時，執行器會選擇按工單號進行seeks跳躍式檢索，如下圖：
- 在不存在exists條件的情況下，執行器選擇了葉節點順序掃描的方式，如下圖：
gt 條件和反序
除了第一次查詢之外，我們對后續的分頁查詢也進行了分析，如下：
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")
上面的陳述句中，主要是增加了$gt: "VXZ190"這一個條件，執行程序如下：
"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1004,
"totalDocsExamined" : 1000,
...
"indexBounds" : {
"oid" : [
"(\"VXZ190\", {})"
],
"lastModifiedTime" : [
"(new Date(1554806697106), new Date(1554803097106))"
]
},
"keysExamined" : 1004,
"seeks" : 5,
可以發現，seeks的數量非常少，而且檢索程序只掃描了1004條記錄，效率是很高的，
那么，是不是意味著在后面的資料中，滿足查詢的條件的記錄非常密集呢？
為了驗證這一點，我們將一開始第一次分頁的查詢做一下調整，改為按工單號降序的方式(從后往前掃描):
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" : 6,
"totalKeysExamined" : 1001,
"totalDocsExamined" : 1000,
...
"direction" : "backward",
"indexBounds" : {
"oid" : [
"[MaxKey, MinKey]"
],
"lastModifiedTime" : [
"(new Date(1554803097106), new Date(1554806697106))"
]
},
"keysExamined" : 1001,
"seeks" : 2,
可以看到，執行的效率更高了，幾乎不需要什么 seeks 操作！
經過一番確認后，我們獲知了在所有資料的分布中，工單號越大的記錄其更新時間值也越大，基本上我們想查詢的目標資料都集中在尾端，
于是就會出現一開始提到的，第一次查詢非常慢甚至超時，而后面的查詢就快了，
上面提到的兩個查詢執行路線如圖所示：
- 加入$gt 條件，從中間開始檢索
- 反序，從后面開始檢索
優化思路
通過分析，我們知道了問題的癥結在于索引的掃描范圍過大，那么如何優化，以避免掃描大量記錄呢？
從現有的索引及條件來看，由于同時存在gt、exists以及葉子節點的時間范圍限定，不可避免的會產生seeks操作，
而且查詢的性能是不穩定的，跟資料分布、具體查詢條件都有很大的關系，
于是一開始所提到的僅僅是增加 socketTimeout 的閾值可能只是治標不治本，一旦資料的索引值分布變化或者資料量持續增大，可能會發生更嚴重的事情，
回到一開始的需求場景，定時器要求讀取每天更新的工單(按工單號排序)，再進行分批處理，
那么，按斬訓零為整的思路，新增一個lastModifiedDay欄位，這個存盤的就是lastModifiedTime對應的日期值(低位取整)，這樣在同一天內更新的工單記錄都有同樣的值，
建立組合索引 {lastModifiedDay:1, oid:1}，相應的查詢條件改為：
{
"lastModifiedDay": new Date("2019-04-09 00:00:00.000")，
"oid": {$gt: "VXZ190"}
}
-- limit 1000
執行結果如下：
"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1000,
"totalDocsExamined" : 1000,
...
"indexBounds" : {
"lastModifiedDay" : [
"(new Date(1554803000000), new Date(1554803000000))"
],
"oid" : [
"(\"VXZ190\", {})"
]
},
"keysExamined" : 1000,
"seeks" : 1,
這樣優化之后，每次查詢最多只掃描1000條記錄，查詢速度是非常快的！
小結
本質上，這就是一種空間換時間的方法，即通過存盤一個額外的索引欄位來加速查詢，通過增加少量的存盤開銷提升了整體的效能，
在對于許多問題進行優化時，經常是需要從應用場景觸發，適當的轉換思路，
比如在本文的問題中，是不是一定要增加欄位呢？如果業務上可以接受不按工單號排序進行讀取，那么僅使用更新時間欄位進行分頁拉取也是可以達到效果的，具體還是要由業務場景來定，
轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/32637.html
標籤：NoSQL