十年河東，十年河西，莫欺少年窮
學無止境，精益求精
首先，先說下自己遇到的真實案例，如下：
我司主做掃碼換電業務，主要設備有換電櫃，智能鋰電池，充電樁等，針對的客戶群體為美團/餓了么等外賣跑腿小哥/小妹，他們通過換電業務，更換電動車的電池。
2021年7月22，公司客戶反饋掃碼換電非常卡，我首先查看了阿里雲消息隊列中的活躍消息是否有堆積，結果發現確實部分消息堆積。
消息怎么會堆積呢？我開了10個偵聽客戶端用於活躍消息的消費，並且每個客戶端都采用了異步多線程的模式進行處理。這使我百思不得其解...
以上截圖便是阿里雲活躍消息個數，活躍消息代表未被消費的消息，我們的設備操作需要即時返回處理結果，因此：一旦堆積，則掃碼換電業務等於攤還...【上圖中的平均值1為正常情況，我們有一次堆積了近400條消息，汗不汗顏...】
阿里雲消息雖然有堆積，但肯定不是阿里雲的問題，畢竟阿里雲是中國乃至世界比較大的公司，雲服務世界上也是排名前幾的。
那么，只能在自己程序上找問題，於是乎，我遠程了偵聽客戶端的服務器，並沒有發現什么，再然后，我去了MongoDb的獨立服務器，通過監控，我發現 Mongodb 服務器的CPU一直高居100%，這尼瑪再多的偵聽客戶端【依賴MOngoDB服務】也無濟於事啊。
問題定位到了，那就是MongoDB服務器CPU消耗過高，是什么操作使一個16核，32G內存服務器CPU消耗這么高呢？
1、我在Robo 3T 1.3.1客戶端上執行如下指令
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 | 跟鎖相關的信息，詳情請參見並發介紹。
說明 db.currentOp文檔請參見
db.currentOp。
|
db.currentOp()查看正在執行的操作，分析是否有不正常耗時的請求正在執行。例如您的業務平時CPU使用率不高，運維管理人員連到MongoDB數據庫執行了一些需要全表掃描的操作導致CPU使用率非常高，業務響應緩慢，此時需要重點關注執行時間非常耗時的操作。
如果您的應用剛剛上線，MongoDB實例的CPU使用率馬上處於持續很高的狀態，執行db.currentOp()，在輸出結果中未發現異常請求，您可參見下述小節分析數據庫慢請求。
分析MongoDB數據庫的慢請求
雲數據庫MongoDB默認開啟了慢請求Profiling ，系統自動地將請求時間超過100ms的執行情況記錄到對應數據庫下的system.profile集合里。
- 通過Mongo Shell連接實例。
詳情請參見Mongo Shell連接單節點實例、Mongo Shell連接副本集實例、Mongo Shell連接分片集群實例或Mongo Shell連接Serverless實例。
- 通過
use <database>命令進入指定數據庫。use mongodbtest
- 執行如下命令，查看該數據下的慢請求日志。
db.system.profile.find().pretty()
- 分析慢請求日志，查找引起MongoDB CPU使用率升高的原因。
以下為某個慢請求日志示例，可查看到該請求進行了全表掃描，掃描了11000000個文檔，沒有通過索引進行查詢。
{ "op" : "query", "ns" : "123.testCollection", "command" : { "find" : "testCollection", "filter" : { "name" : "zhangsan" }, "$db" : "123" }, "keysExamined" : 0, "docsExamined" : 11000000, "cursorExhausted" : true, "numYield" : 85977, "nreturned" : 0, "locks" : { "Global" : { "acquireCount" : { "r" : NumberLong(85978) } }, "Database" : { "acquireCount" : { "r" : NumberLong(85978) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(85978) } } }, "responseLength" : 232, "protocol" : "op_command", "millis" : 19428, "planSummary" : "COLLSCAN", "execStats" : { "stage" : "COLLSCAN", "filter" : { "name" : { "$eq" : "zhangsan" } }, "nReturned" : 0, "executionTimeMillisEstimate" : 18233, "works" : 11000002, "advanced" : 0, "needTime" : 11000001, "needYield" : 0, "saveState" : 85977, "restoreState" : 85977, "isEOF" : 1, "invalidates" : 0, "direction" : "forward", ....in" } ], "user" : "root@admin" }
通常在慢請求日志中，您需要重點關注以下幾點。
- 全表掃描（關鍵字： COLLSCAN、 docsExamined ）
- 全集合（表）掃描COLLSCAN 。
當一個操作請求（如查詢、更新、刪除等）需要全表掃描時，將非常占用CPU資源。在查看慢請求日志時發現COLLSCAN關鍵字，很可能是這些查詢占用了CPU資源。說明 如果這種請求比較頻繁，建議對查詢的字段建立索引的方式來優化。
- 通過查看docsExamined的值，可以查看到一個查詢掃描了多少文檔。該值越大，請求所占用的CPU開銷越大。
- 全集合（表）掃描COLLSCAN 。
- 不合理的索引（關鍵字： IXSCAN、keysExamined ）
說明
- 索引不是越多越好，索引過多會影響寫入、更新的性能。
- 如果您的應用偏向於寫操作，索引可能會影響性能。
通過查看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相同取值少關於{y: 1} 與 {y: 1, x: 1} 的區別，可參見MongoDB索引原理及復合索引官方文檔。
- 大量數據排序（關鍵字： SORT、hasSortStage ）
當查詢請求里包含排序的時候， system.profile 集合里的hasSortStage字段會為 true 。如果排序無法通過索引滿足，MongoDB會在查詢結果中進行排序。而排序這個動作將非常消耗CPU資源，這種情況需要對經常排序的字段建立索引的方式進行優化。說明 當您在system.profile集合里發現SORT關鍵字時，可以考慮通過索引來優化排序。
其他還有諸如建立索引、aggregation（遍歷、查詢、更新、排序等動作的組合） 等操作也可能非常耗CPU資源，但本質上也是上述幾種場景.
上述文檔參考自：阿里雲。https://help.aliyun.com/document_detail/62224.html
最終助我解決問題的是這條指令：
db.currentOp()
這條指令的輸出結果指向的其中一張表的操作，於是，我通過排查全公司所有涉及到這張表的MOngodb操作，發現了一個查詢【每秒都會查】非常消耗CPU，通過代碼的改進，最終使Cpu降了下來。有圖為證，如下：
最后，針對 db.currentOp() 指令的輸出，做一個詳細說明：
db.currentOp()
db.currentOp是個好東西，顧名思義，就是當前的操作。在mongodb中可以查看當前數據庫上此刻的操作語句信息，包括insert/query/update/remove/getmore/command等多種操作。直接執行
db.currentOp()一般返回一個空的數組，我們可以指定一個參數true，這樣就返回用戶connections與系統cmmand相關的操作。下面看個列子：
db.currentOp(true) 會返回很多信息：
db.currentOp()
查看數據庫當前執行什么操作。
用於查看長時間運行進程。
通過（執行時長、操作、鎖、等待鎖時長)等條件過濾。
重點關注以下幾個字段：
| 字段 | 說明 |
|---|---|
| client | 請求是由哪個客戶端發起的。 |
| opid | 操作的opid，有需要的話，可以通過db.killOp(opid) 直接終止該操作。 |
| secs_running/microsecs_running | 這個值重點關注，代表請求運行的時間，如果這個值特別大，請看看請求是否合理。 |
| query/ns | 這個字段能看出是對哪個集合正在執行什么操作。 |
| lock* | - 還有一些跟鎖相關的參數，需要了解可以看官網文檔，本文不做詳細介紹。 - db.currentOp文檔請參見：db.currentOp 。 |
返回信息：
{ "inprog": [ { "host" : <string>, "desc" : <string>, "connectionId" : <number>, "client" : <string>, "appName" : <string>, "clientMetadata" : <document>, "active" : <boolean>, "currentOpTime" : <string>, "opid" : <number>, "secs_running" : <NumberLong()>, "microsecs_running" : <number>, "op" : <string>, "ns" : <string>, "command" : <document>, "originatingCommand" : <document>, "planSummary": <string>, "msg": <string>, "progress" : { "done" : <number>, "total" : <number> }, "killPending" : <boolean>, "numYields" : <number>, "locks" : { "Global" : <string>, "MMAPV1Journal" : <string>, "Database" : <string>, "Collection" : <string>, "Metadata" : <string>, "oplog" : <string> }, "waitingForLock" : <boolean>, "lockStats" : { "Global": { "acquireCount": { "r": <NumberLong>, "w": <NumberLong>, "R": <NumberLong>, "W": <NumberLong> }, "acquireWaitCount": { "r": <NumberLong>, "w": <NumberLong>, "R": <NumberLong>, "W": <NumberLong> }, "timeAcquiringMicros" : { "r" : NumberLong(0), "w" : NumberLong(0), "R" : NumberLong(0), "W" : NumberLong(0) }, "deadlockCount" : { "r" : NumberLong(0), "w" : NumberLong(0), "R" : NumberLong(0), "W" : NumberLong(0) } }, "MMAPV1Journal": { ... }, "Database" : { ... }, ... } }, ... ], "fsyncLock": <boolean>, "info": <string>, "ok": 1 }
返回字段說明：
currentOp.host：運行該操作的主機的名稱。
currentOp.desc：客戶端的描述。這個字符串包括connectionId。
currentOp.connectionId：操作起源的連接的標識符。
currentOp.client：包含有關操作起源的信息的字符串。
對於多文檔事務，客戶機存儲要在事務中運行操作的最新客戶機的信息。
currentOp.appName：包含發出請求的客戶機類型信息的字符串。
currentOp.clientMetadata：關於客戶端的附加信息。
對於多文檔事務，客戶機存儲要在事務中運行操作的最新客戶機的信息。
currentOp.currentOpTime：操作的開始時間。新版本3.6。
currentOp.lsid：會話標識符。僅當操作與會話關聯時才顯示。新版本3.6。
currentOp.transaction：包含多文檔事務信息的文檔。僅當操作是事務的一部分時才出現。新版本4.0。
currentOp.transaction.parameters：包含多文檔事務信息的文檔。僅當操作是事務的一部分時才出現。新版本4.0。
currentOp.transaction.parameters.txnNumber：事務數量。僅當操作是事務的一部分時才出現。新版本4.0。
currentOp.transaction.parameters.autocommit：一個布爾標志，指示事務的自動提交是否打開。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.transaction.parameters.readConcern：事務的read關注點。多文檔事務支持讀取關注點“快照”、“本地”和“多數”。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.transaction.readTimestamp：事務中的操作正在讀取快照的時間戳。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.transaction.startWallClockTime：事務開始的日期和時間(帶有時區)。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.transaction.timeOpenMicros事務的持續時間(以微秒為單位)。添加到timeInactiveMicros的timeActiveMicros值應該等於timeOpenMicros。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.transaction.timeActiveMicros：交易活動的總時間;例如，當事務運行操作時。添加到timeInactiveMicros的timeActiveMicros值應該等於timeOpenMicros。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.transaction.timeInactiveMicros：該事務處於非活動狀態的總時間;例如，當事務沒有運行任何操作時。添加到timeActiveMicros的timeInactiveMicros值應該等於timeOpenMicros。僅當操作是事務的一部分時才出現。
currentOp.transaction.expiryTime：事務超時並中止的日期和時間(帶有時區)。
currentOp.transaction：呼氣時間等於current .transaction。startWallClockTime + transactionLifetimeLimitSeconds。有關更多信息，請參見事務的運行時限制。僅當操作是事務的一部分時才出現。新版本4.0.2。
currentOp.opid：操作的標識符。您可以將此值傳遞給mongo shell中的db.killOp()來終止操作。
警告
非常謹慎地終止運行操作。只使用db.killOp()終止客戶機發起的操作，而不終止內部數據庫操作。
currentOp.active：指定操作是否已啟動的布爾值。如果操作已經啟動，則值為true;如果操作是空閑的，則值為false，例如空閑連接或當前空閑的內部線程。一個操作可以是活動的，即使該操作已被另一個操作取代。在3.0版本中進行了更改:對於一些非活動的后台線程，例如非活動的signalProcessingThread, MongoDB會抑制各種空字段。
currentOp.secs_running：操作持續時間(以秒為單位)。MongoDB通過從操作開始時減去當前時間來計算這個值。僅當操作正在運行時才出現;也就是說，如果active為真。
currentOp.microsecs_running：操作持續時間(以微秒為單位)。MongoDB通過從操作開始時減去當前時間來計算這個值。僅當操作正在運行時才出現;也就是說，如果active為真。
currentOp.op：標識操作類型的字符串。可能的值是:
"none""update""insert""query""command""getmore""remove""killcursors"
“query”操作包括讀取操作。
“command”操作包括大多數命令，如createIndexes和findandmodify。
在3.0版本中更改:使用insert、update和delete命令的寫操作分別為op顯示“insert”、“update”和“remove”。以前的版本在“query”操作下包含這些寫命令。
修改版本3.2:大多數命令，包括createIndexes和findandmodify，都為op顯示“command”。以前版本的MongoDB在“query”操作下包含了這些命令。
currentOp.ns：操作目標的命名空間。名稱空間由數據庫名和集合名組成，集合名與點(.)連接;也就是說,“<數據庫>。<收藏>”。
currentOp.command：在3.6版中進行了更改。包含與此操作關聯的完整命令對象的文檔。如果命令文件超過1 kb，則文件的形式如下:
"command" : { "$truncated": <string>, "comment": <string> }
$truncated字段包含文檔的字符串摘要，如果存在，則不包括文檔的注釋字段。如果摘要仍然超過1 kb，則進一步截斷它，用字符串末尾的省略號(…)表示。
如果將注釋傳遞給操作，則會顯示注釋字段。
下面的示例輸出包含一個命令對象，用於在一個名為test的數據庫中對一個集合的命名項執行查找操作:
"command" : { "find" : "items", "filter" : { "sku" : 1403978 }, "$db" : "test" }
下面的示例輸出包含用於getMore操作的命令對象，getMore操作是由一個命令生成的，該命令的游標id為80336119321，用於一個名為test的數據庫中的集合命名項:
"command" : { "getMore" : NumberLong("80336119321"), "collection" : "items", "$db" : "test" }
currentOp.originatingCommand：版本3.6中的更改:對於從游標檢索下一批結果的“getmore”操作，originatingCommand字段包含最初創建該游標的完整命令對象(例如find或aggregate)。
currentOp.planSummary：包含查詢計划的字符串，用於幫助調試慢速查詢。
currentOp.client：IP地址(或主機名)和發起操作的客戶機連接的臨時端口。如果您的inprog數組有來自許多不同客戶端的操作，請使用此字符串將操作與客戶端關聯起來。
currentOp.appName：新版本3.4。運行該操作的客戶機應用程序的標識符。使用appName連接字符串選項為appName字段設置自定義值。
currentOp.locks：在3.0版本中進行了更改。locks文檔報告操作當前持有的鎖的類型和模式。可能的鎖類型如下:
鎖類型 描述Global 表示全局鎖。
MMAPV1Journal 表示用於同步日志寫入的MMAPv1存儲引擎特定鎖;對於非mmapv1存儲引擎，MMAPV1Journal的模式為空。Database 表示數據庫鎖。Collection 表示集合鎖。Metadata 表示元數據鎖。
oplog 表示oplog上的鎖。
可能的模式如下:
鎖定模式 描述
R 表示共享鎖。
W 表示排他(X)鎖。
r 表示共享的意圖(IS)鎖。
w 表示意圖獨占(IX)鎖。
currentOp.msg：msg提供一條消息，描述操作的狀態和進度。對於索引或mapReduce操作，字段報告完成百分比。
currentOp.progress：報告mapReduce或索引操作的進度。進度字段對應於msg字段中的完成百分比。進度說明了以下信息:
currentOp.progress.done：報告完成的數字。
currentOp.progress.total：報告總數。
currentOp.killPending：如果當前操作被標記為要終止，則返回true。當操作遇到下一個安全終止點時，操作將終止。
currentOp.numYields：numyield是一個計數器，它報告操作已經讓步多少次，以允許其他操作完成。
通常，當需要訪問MongoDB尚未完全讀入內存的數據時，操作會產生收益。這允許其他在內存中有數據的操作在MongoDB為生成操作讀入數據時快速完成。
currentOp.fsyncLock：指定當前是否鎖定fsync寫入/快照的數據庫。只有鎖定時才會出現;例如，如果fsyncLock為真。
currentOp.info：有關如何從db.fsyncLock()解鎖數據庫的信息。只有當fsyncLock為真時才會出現。
currentOp.lockStats：對於每種鎖類型和模式(參見currentOp)。)，返回以下信息:
currentOp.lockStats.acquireCount：操作以指定模式獲取鎖的次數。
currentOp.lockStats.acquireWaitCount：操作必須等待acquirecallock獲取的次數，因為鎖處於沖突模式。acquireWaitCount小於或等於acquirecore。
currentOp.lockStats.timeAcquiringMicros：操作必須等待獲取鎖的累積時間(以微秒為單位)。時間獲取微s除以acquireWaitCount給出了特定鎖定模式的平均等待時間。
currentOp.lockStats.deadlockCount：在等待鎖獲取時，操作遇到死鎖的次數。
1：查看MongoDB當前正在做哪些操作？
db.currentOp() 等同於： db.$cmd.sys.inprog.findOne()
2：查看當前有多少個連接？
db.serverStatus().connections
3：詳解currentOp()
gechongrepl:PRIMARY> db.currentOp() { "inprog" : [ { "opid" : 6222, #進程號 "active" : true, #是否活動狀態 "secs_running" : 3,#操作運行了多少秒 "microsecs_running" : NumberLong(3662328),#操作持續時間(以微秒為單位)。MongoDB通過從操作開始時減去當前時間來計算這個值。 "op" : "getmore",#操作類型，包括(insert/query/update/remove/getmore/command) "ns" : "local.oplog.rs",#命名空間 "query" : {#如果op是查詢操作，這里將顯示查詢內容；也有說這里顯示具體的操作語句的 }, "client" : "192.168.91.132:45745",#連接的客戶端信息 "desc" : "conn5",#數據庫的連接信息 "threadId" : "0x7f1370cb4700",#線程ID "connectionId" : 5,#數據庫的連接ID "waitingForLock" : false,#是否等待獲取鎖 "numYields" : 0, "lockStats" : { "timeLockedMicros" : {#持有的鎖時間微秒 "r" : NumberLong(141),#整個MongoDB實例的全局讀鎖 "w" : NumberLong(0)#整個MongoDB實例的全局寫鎖 }, "timeAcquiringMicros" : {#為了獲得鎖，等待的微秒時間 "r" : NumberLong(16),#整個MongoDB實例的全局讀鎖 "w" : NumberLong(0)#整個MongoDB實例的全局寫鎖 } } } ] }
@天才卧龍的博客