背景
最近線上的一個工單分析服務一直不大穩定,監控平臺時不時發出數據庫操作超時的告警。
運維兄弟溝通後,發現在每天凌晨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條記錄,查詢速度是非常快的!
小結
本質上,這就是一種空間換時間的方法,即通過存儲一個額外的索引字段來加速查詢,通過增加少量的存儲開銷提升了整體的效能。
在對於許多問題進行優化時,經常是需要從應用場景觸發,適當的轉換思路。
比如在本文的問題中,是不是一定要增加字段呢?如果業務上可以接受不按工單號排序進行讀取,那麼僅使用更新時間字段進行分頁拉取也是可以達到效果的,具體還是要由業務場景來定。
華為技術專家,多年互聯網研發/架設經驗,關注NOSQL 中間件高可用及彈性擴展,在分佈式系統架構性能優化方面有豐富的實踐經驗,目前從事物聯網平臺研發工作,致力於打造大容量高可用的物聯網服務。
MongoDB中文社區,一個mongoers都會來的社區
關注我們,獲取更多精彩內容
閱讀更多 MongoDB中文社區 的文章