十年河东，十年河西，莫欺少年穷
学无止境，精益求精
首先，先说下自己遇到的真实案例，如下：
我司主做扫码换电业务，主要设备有换电柜，智能锂电池，充电桩等，针对的客户群体为美团/饿了么等外卖跑腿小哥/小妹，他们通过换电业务，更换电动车的电池。
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实例的全局写锁 } } } ] }
@天才卧龙的博客