Mongo CPU 過載調查及日誌

Mongo CPU 過載調查及日誌#

Created: June 22, 2021 5:52 PM

現象#

生產環境主庫出現周期性 (04:05, 04:15, 07:05, 07:15, 11:05) 和非周期 (04:15–04:30， 11：05-11：15) CPU 利用率 5 分鐘內超過 80%。

由於 CPU 超時是周期性，並且是非連續性的。因此合理懷疑是定時任務出現了問題。
根據 AWS EC2 上的預警時間去篩選相關的定時任務。

CPU 過載的客觀原因#

全表掃描 (collection scan)#

What：COLLSCAN 全集合 / 表掃描，CPU 高消耗操作，會對表內或庫內所有的記錄掃描一遍，按照條件過濾。在 profile 集合或日誌中發現 COLLSCAN 關鍵詞，並且此操作比較頻繁，則需要針對查詢字段建立索引來優化。
How to locate: 可以通過 Profile 中的 planSummary 參數來判斷是否發生了慢查詢全表搜索。
How to address: 建立合理的索引

不合理索引#

What：不合理的索引會造成查詢時掃描過多的索引，造成 CPU 高開銷。
How to locate: 可以通過 system.profile 或者 Query Plans 的 planSummary 值為 IXSCAN 來定位是索引查詢，並根據 keysExamined 來確認索引是否合理。
How to address：建立合理的索引

大數據量排序#

What: 當查詢時的排序請求無法通過索引完成時，Mongo 會將數據放入到內存中排序，如果數據量過大會造成 CPU 過高。
How to locate: 當你在 system.profile 集合發現 SORT 關鍵字時，就可以考慮通過索引來優化排序。當請求包含排序階段時， system.profile 裡的 hasSortStage 字段會為 true。
How to address: 建立用於排序的索引

超出服務能力#

當如上幾大問題全部排查完了，所有的 query 和索引都是科學的，那麼說明服務的容量跟不上業務的體量了。
此時需要考慮升級配置。

Mongo 如何科學得建立索引

多看文檔（[https://docs.mongodb.com/manual/indexes/]）
區分度高：distinc value count/total value count
無 Null 值：null 不建立索引
高頻用於更新、查詢 filter
升序、降序：
- 單字段索引中，升降序效果一樣，因為 mongo 的索引是排序後向上下移動查詢的。
- 在聯合索引中，第二個索引字段的升降序就會影響查詢效果了。例如第二個字段是訂單時間，那麼降序索引可以在更新訂單時更快的鎖定訂單。
不可以盲目的建立索引，索引也有建立和插入時的創建成本。
這個話題太大，之後展開

監控及發現上述問題#

CurrentOp 當前操作信息#

高峰時期，使用 db.currentOp () 對超頻 DB 進行狀態檢查，返回值的含義見 ([https://docs.mongodb.com/manual/reference/command/currentOp/#currentop-output-fields])

Profiler 性能分析日誌#

Mongo 查詢性能日誌收集功能，默認關閉。由於對數據庫性能有輕微的影響，因此推薦只在預發環境中開啟。
主要功能是將數據庫命令及其運行信息存儲到每個 db 下的 system 文件夾 profile collection 中，這個 collection 的大小是固定的，超出設定大小後，自動刪除舊日誌，目前來看，最多可以存放最近 950 條記錄 (感謝對賬的大規模慢查詢)。
Profiler 是日誌版的 currentOp, 因為兩者的返回參數是完全一樣的。
Profiler 可以通過 db.setProfilingLevel (level) 來設置，level 有三級：0 (關閉)，1 (根據slowms閾值來篩選記錄，slowms 為操作運行的毫秒數)，2 (記錄所有操作日誌)。
可以通過 db.getProfilingStatus () 來獲取當前 db 的 Profiler 設置。

著重注意幾個參數#

secs_running

操作運行的時間，秒級別

microsecs_running

操作運行的時間，毫秒級別
多久算是慢？
- Mongo 默認是 100ms 以上的查詢就是慢查詢，實際情況下，我們有 30s 的全表掃描查詢。因此，我先設置為 200，最後可以根據業務複雜度討論得出。

planSummary

COLLSCAN： 全表掃描
IXSCAN { field_name: 1 }：索引查詢 內部標註用了什麼索引
IDHACK： 主鍵索引查詢 跳過其他的查詢 plan，根據主鍵提供更優的查詢，出現在查詢 query 中有_id 值時

keysExamined

用於判斷對這個查詢而言，現有的索引是否合理。
表示一次查詢完成前掃描了多少索引，值越大，CPU 開銷越大

定位問題代碼#

周期性#

04:05 (5 分鐘均值，因此 04:00 起，UTC+8=12:05)

sync_transaction_data
任務 A (4 小時一次)(主要是 MySQL Membership 讀取，及 Redis 中的 api db 寫入)

04:15(12:15)

任務 B

07:05(15:05)

sync_transaction_data(下午三點第二次)
任務 C (主要操作 MySQL 讀庫)

11:05(19:05)

sync_transaction_data(晚上七點第三次)
任務 C

非周期性#

(04:15–04:30， 11：05-11：15)，根據時間來看，應該是sync_transaction_data的後續問題
但仍舊可以用profile圍觀一下

其他可能原因#

排除了周期及非周期的問題，如果還沒有解決，就繼續研究。

實踐#

開啟 Freeze 環境中的 Profile，設置為 1，並定閾值為 200
打開 Flower 監控異步任務運行情況
打開 AWS CloudWatch 監控 CPU 使用情況
進入 Freeze Shell 執行 sync_transaction_data.delay ()
打開 MongoDB，查看 Bill 下的 profile collection 中的慢查詢日誌
發現 900 多條這類日誌 [1], 可以注意到這個是一個全表掃描。
三個字段 transaction_time, channel, settlement_sign，後兩個一個是只有 5 種類別的枚舉字段，一個是只有 0 和 1 的 Boolean 字段。區分度太低。只有第一個 transaction_time 字段適合。
加上索引後，CPU 佔用率用 99.9% 降到 3%，異步任務時間從 900s 降到 19s

維護與防範#

Freeze 環境打開 Profile 性能監控
定期檢查並處理慢查詢

{
  "op":"query",
  "ns":"bill.transaction",
  "keysExamined":0,
  "query":{  
     "find":"transaction",
     "filter":{  
        "transaction_time":{  
           "$gte":{"$date":"2018-05-20T23:00:00.000+0000"},
           "$lte":{"$date":"2018-05-21T22:59:59.999+0000"}},
        "channel":"非再惠渠道",
        "settlement_sign":{  
           "$in":[1]}}
  },
  "docsExamined":2882636,
  "cursorExhausted":true,
  "numYield":22635,
  "nreturned":0,
  "responseLength":104,
  "protocol":"op_query",
  "millis":15131,
  "planSummary":"COLLSCAN",
  "execStats":{
     "stage":"COLLSCAN",
     "nReturned":0,
     "executionTimeMillisEstimate":14727,
     "works":2882638,
     "advanced":0,
     "needTime":2882637,
     "needYield":0,
     "saveState":22635,
     "restoreState":22635,
     "isEOF":1,
     "invalidates":0,
     "direction":"forward",
     "docsExamined":2882636
  },
  "ts":{
     "$date":"2018-05-23T12:30:42.539+0000"
  }
}