解決排查 mongodb cpu使用率過高

前言

通過 top 命令，可以看到 MongoDB 的 CPU 使用率過高，CPU 過高會導致數據讀寫、處理異常緩慢，還會出現被系統抹殺進程的風險，這個問題 99.9999% 的可能性是用戶使用上不合理導致的，本文介紹如何從應用的角度如何排查 MongoDB CPU 利用率過高的問題。

分析數據庫正在執行的請求

執行 db.currentOp() 命令，可以查看數據庫當前正在執行的操作

該命令的輸出示例如下：

{
        "desc" : "conn632530",
        "threadId" : "140298196924160",
        "connectionId" : 632530,
        "client" : "11.192.159.236:57052",
        "active" : true,
        "opid" : 1008837885,
        "secs_running" : 0,
        "microsecs_running" : NumberLong(70),
        "op" : "update",
        "ns" : "mygame.players",
        "query" : {
            "uid" : NumberLong(31577677)
        },
        "numYields" : 0,
        "locks" : {
            "Global" : "w",
            "Database" : "w",
            "Collection" : "w"
        },
        ....
    },

需要重點關注以下幾個字段

字段	返回值說明
client	該請求是由哪個客戶端發起的。
opid	操作的唯一標識符。 說明 如果有需要，可以通過db.killOp(opid)直接終止該操作。
secs_running	表示該操作已經執行的時間，單位為秒。如果該字段返回的值特別大，需要查看請求是否合理。
microsecs_running	表示該操作已經執行的時間，單位為微秒。如果該字段返回的值特別大，需要查看請求是否合理。
ns	該操作目標集合。
op	表示操作的類型。通常是查詢、插入、更新、刪除中的一種。
locks	跟鎖相關的信息，詳情請參見並發介紹。

分析數據庫慢請求

MongoDB 支持 profiling 記錄慢查詢日志功能，將請求的執行情況記錄到同 DB 下的 system.profile 集合里，它可以幫助我們進行優化我們的 sql，並提高我們系統的穩定性和流暢性。

默認情況下是關閉的，我們可以在數據庫級別上或者是節點級別上配置。

profiling 有3種模式，狀態碼及相關描述：

• 0：表示關閉 profiling 慢查詢，默認情況下
• 1：表示超過閾值的查詢收集，針對所有請求開啟 profiling，將所有請求的執行都記錄到 system.profile 集合
• 2：為所有數據庫開啟慢查詢記錄，收集所有的數據 針對慢請求 profiling，將超過一定閾值的請求，記錄到 system.profile 集合

MongoDB慢查詢兩種啟動方式

通過 MongoDB shell 啟用

為所有數據庫開啟慢查詢記錄

db.setProfilingLevel(2)

禁用慢查詢

db.setProfilingLevel(0)

指定 test 數據庫，並指定閾值慢查詢 ，超過20毫秒的查詢被記錄

use test

db.setProfilingLevel(1, { slowms: 20 })

隨機采集慢查詢的百分比值，sampleRate 值默認為1，表示都采集，0.42 表示采集42%的內容

db.setProfilingLevel(1, { sampleRate: 0.42 })

查詢慢查詢級別和其它信息

db.getProfilingStatus()

僅返回慢查詢級別

db.getProfilingLevel()

通過配置文件啟用

在 ini 配置文件 mongodb.conf 添加以下參數， profile 參數是設置開啟等級，slowms 是設置閾值

profile = 1

slowms = 300

在 YAML 文件配置

operationProfiling:
   mode: <string>  # 默認為 off，可選值 off、slowOp(對應上面的等級 1)、all(對應上面的等級 2)
   slowOpThresholdMs: <int> # 閾值，默認值為100，單位毫秒
   slowOpSampleRate: <double> #  隨機采集慢查詢的百分比值，sampleRate 值默認為1，表示都采集，0.42 表示采集42%的內容

常用命令和示例

# 查詢慢請求日志
db.system.profile.find().pretty()

# 查詢最近的10個慢查詢日志
db.system.profile.find().limit(10).sort( { ts : -1 } ).pretty()

# 查詢除命令類型為 command 的日志
db.system.profile.find( { op: { $ne : 'command' } } ).pretty()

# 查詢數據庫為 mydb 集合為 test 的 日志
db.system.profile.find( { ns : 'mydb.test' } ).pretty()

# 查詢 低於 5毫秒的日志
db.system.profile.find( { millis : { $gt : 5 } } ).pretty()

# 查詢時間從 2012-12-09 3點整到 2012-12-09 3點40分之間的日志
db.system.profile.find({
  ts : {
    $gt: new ISODate("2012-12-09T03:00:00Z"),
    $lt: new ISODate("2012-12-09T03:40:00Z")
  }
}).pretty()

MongoDB慢日志解析

官方文檔：https://docs.mongodb.com/manual/reference/database-profiler/index.html

{
   "op" : "query",   # 操作類型，值可為command、count、distinct、geoNear、getMore、group、insert、mapReduce、query、remove、update
   "ns" : "test.report", # 操作的數據庫和集合
   "command" : {     # 命令
      "find" : "report",  # 操作的集合
      "filter" : { "a" : { "$lte" : 500 } }, # 查詢條件
      "lsid" : {    
         "id" : UUID("5ccd5b81-b023-41f3-8959-bf99ed696ce9") #用戶的會話id
      },
      "$db" : "test"  # 操作的數據庫
   },
   "cursorid" : 33629063128,  # query和getmore 的游標id
   "keysExamined" : 101, # MongoDB為執行操作而掃描的索引鍵的數量
   "docsExamined" : 101, # MongoDB為了執行操作而掃描的集合中的文檔數。
   "numYield" : 2, # 讓步次數，操作時讓其他的操作完成的次數。
   "nreturned" : 101, # 操作返回的文檔數
   "queryHash" : "811451DD", # 查詢的hash值
   "planCacheKey" : "759981BA", 
   "locks" : {  # 操作期間的鎖和所的類型
      "Global" : {  #表示全局鎖定
         "acquireCount" : { #鎖定的次數
            "r" : NumberLong(3)  # 表示共享鎖 
         }
      },
      "Database" : {   # 數據庫鎖
         "acquireCount" : { "r" : NumberLong(1) },
         "acquireWaitCount" : { "r" : NumberLong(1) },
         "timeAcquiringMicros" : { "r" : NumberLong(69130694) }
      },
      "Collection" : {  # 集合鎖
         "acquireCount" : { "r" : NumberLong(1) }
      }
   },
   "storage" : { # 儲存
      "data" : {
         "bytesRead" : NumberLong(14736), #操作 從磁盤放到緩存的數據的字節數
         "timeReadingMicros" : NumberLong(17) # 操作 花費在磁盤讀取的時間，以微妙為單位
      }
   },
   "responseLength" : 1305014, # 操作返回結果的文檔長度，單位為字節
   "protocol" : "op_msg", # 消息的協議
   "millis" : 69132, # 從 MongoDB 操作開始到結束耗費的時間
   "planSummary" : "IXSCAN { a: 1, _id: -1 }",  # 摘要
   "execStats" : {  # 操作執行過程中的詳細信息
      "stage" : "FETCH", # 操作形式 ，COLLSCAN 用於集合掃描，IXSCAN 用於掃描索引鍵，FETCH 用於檢索文檔
      "nReturned" : 101, # 返回的文檔數量
      "executionTimeMillisEstimate" : 0,
      "works" : 101,
      "advanced" : 101,
      "needTime" : 0,
      "needYield" : 0,
      "saveState" : 3,
      "restoreState" : 2,
      "isEOF" : 0,
      "invalidates" : 0,
      "docsExamined" : 101,
      "alreadyHasObj" : 0,
      "inputStage" : {
         ...
      }
   },
   "ts" : ISODate("2019-01-14T16:57:33.450Z"), #操作的時間戳
   "client" : "127.0.0.1",  # 客戶端的ip
   "appName" : "MongoDB Shell", #客戶端應用標識符
   "allUsers" : [
      {
         "user" : "someuser", # 用戶
         "db" : "admin"  # 驗證的數據庫
      }
   ],
   "user" : "someuser@admin"  # 經過驗證的用戶
}

CPU殺手1：全表掃描
全集合（表）掃描 COLLSCAN，當一個查詢（或更新、刪除）請求需要全表掃描時，是非常耗CPU資源的，所以當你在 system.profile 集合 或者 日志文件發現 COLLSCAN 關鍵字時，就得注意了，很可能就是這些查詢吃掉了你的 CPU 資源；確認一下，如果這種請求比較頻繁，最好是針對查詢的字段建立索引來優化。

一個查詢掃描了多少文檔，可查看 system.profile 里的 docsExamined 的值，該值越大，請求CPU開銷越大。

關鍵字：COLLSCAN、 docsExamined

CPU殺手2：不合理的索引
有的時候，請求即使查詢走了索引，執行也很慢，通常是因為合理建立不太合理（或者是匹配的結果本身就很多，這樣即使走索引，請求開銷也不會優化很多）。

通過查看 keysExamined 字段，可以查看到一個使用了索引的查詢，掃描了多少條索引。該值越大，CPU開銷越大。

如果索引建立的不太合理，或者是匹配的結果很多。這樣即使使用索引，請求開銷也不會優化很多，執行的速度也會很慢。

如下所示，假設某個集合的數據，x字段的取值很少（假設只有1、2），而y字段的取值很豐富。

{ x: 1, y: 1 }
{ x: 1, y: 2 }
{ x: 1, y: 3 }
......
{ x: 1, y: 100000} 
{ x: 2, y: 1 }
{ x: 2, y: 2 }
{ x: 2, y: 3 }
......
{ x: 1, y: 100000} 

要實現 {x: 1: y: 2} 這樣的查詢

db.createIndex( {x: 1} )         效果不好，因為x相同取值太多
db.createIndex( {x: 1, y: 1} )   效果不好，因為x相同取值太多
db.createIndex( {y: 1 } )        效果好，因為y相同取值很少
db.createIndex( {y: 1, x: 1 } )  效果好，因為y相同取值少

一個走索引的查詢，掃描了多少條索引，可查看 system.profile 里的 keysExamined 字段，該值越大，CPU 開銷越大。

關鍵字：IXSCAN、keysExamined

• 索引不是越多越好，索引過多會影響寫入、更新的性能。
• 如果您的應用偏向於寫操作，索引可能會影響性能。

CPU殺手3：大量數據排序
當查詢請求里包含排序的時候，如果排序無法通過索引滿足，MongoDB 會在內存李結果進行排序，而排序這個動作本身是非常耗 CPU 資源的，優化的方法仍然是建立索引，對經常需要排序的字段，建立索引。

當你在 system.profile 集合 或者 日志文件發現 SORT 關鍵字時，就可以考慮通過索引來優化排序。當請求包含排序階段時， system.profile 里的 hasSortStage 字段會為 true。

關鍵字：SORT、hasSortStage

其他還有諸如建索引，aggregationv 等操作也可能非常耗 CPU 資源，但本質上也是上述幾種場景；建索引需要全表掃描，而 vaggeregation 也是遍歷、查詢、更新、排序等動作的組合。

服務能力評估

經過上述分析數據庫正在執行的請求和分析數據庫慢請求兩輪優化之后，你發現整個數據庫的查詢非常合理，所有的請求都是高效的走了索引，基本沒有優化的空間了，那么很可能是你機器的服務能力已經達到上限了，應該升級配置了（或者通過 sharding 擴展）。

當然最好的情況時，提前對 MongoDB 進行測試，了解在你的場景下，對應的服務能力上限，以便及時擴容、升級，而不是到 CPU 資源用滿，業務已經完全撐不住的時候才去做評估。

巨人的肩膀

https://www.cnblogs.com/operationhome/p/10728654.html
https://help.aliyun.com/document_detail/62224.html
https://mongoing.com/archives/3998