持续创作，加速成长！这是我参与「掘金日新计划 · 6 月更文挑战」的第6天，点击查看活动详情
1、前言
今天早上一觉醒来，打开微信，发现昨天晚上11点钟，我组长给我发了条紧急消息：线上的mongo服务器CPU占用率一直持续徘徊在90%,让我抓紧排查下。说实话，这还是我第一次排查线上mongo，特地记录下排查步骤。
2、排查索引是否正常
首先CPU占用率很高，一般就是读操作很慢，或者写操作很慢。线上环境3个月的数据量在80w左右，应该不是写操作慢的问题。因为用到mongo的功能都是我自己负责开发的，创建集合时，都加上了索引的，而且这是上线5个月来第一次出现这种问题，就感觉很奇怪。
#还是先查看下索引信息：
#切换到当前数据库
use userbehavior
#查看集合的索引信息
db.user_behavior.stats({indexDetails:true})
线上的mongo版本是社区版4.0，不知为何上述命令执行总报错。
然后找到mongo文档，用下面的命令可以正常执行。
#查看mongo慢查询日志
db.system.profile.find().pretty()
#执行结果：
{
"op": "command",
"ns": "admin.system.users",
"command": {
"saslStart": 1,
"mechanism": "SCRAM-SHA-1",
"payload": {
"type": 0,
"data": "biwsbj1tb25pdG9yLHI9TURJMU5qQTNOalV3TXpVeU1EQXlOREU9"
},
"autoAuthorize": 1,
"$db": "admin"
},
"numYield": 0,
"locks": {
"Global": {
"acquireCount": {
"r": 1
}
},
"Database": {
"acquireCount": {
"r": 1
}
},
"Collection": {
"acquireCount": {
"r": 1
}
}
},
"responseLength": 312,
"protocol": "op_query",
"millis": 102,
"ts": "ISODate(\"2022-04-27T01:43:33.368Z\")",
"client": "",
"allUsers": [],
"user": ""
}
从执行结果来看，好像并没有找到慢查询情况。但CPU占用率依旧在90%。于是换如下命令排查：
#查看当前正在执行的请求
db.currentOp()
#执行结果：
"inprog": [
{
"host": "host-0.0.0.0",
"desc": "conn656",
"connectionId": 656,
"client": "0.0.0.0",
"clientMetadata": {
"driver": {
"name": "mongo-java-driver",
"version": "unknown"
},
"os": {
"type": "Linux",
"name": "Linux",
"architecture": "amd64",
"version": "3.10.0-1160.6.1.el7.x86_64"
},
"platform": "Java/Oracle Corporation/1.8.0_111-8u111-b14-2~bpo8+1-b14"
},
"active": true,
"currentOpTime": "2022-05-31T02:04:04.233+0000",
"opid": 883510,
"secs_running": 33,
"microsecs_running": 33453342,
"op": "query",
"ns": "userbehavior.user_behavior",
"command": {
"find": "user_behavior",
"filter": {
"user_common_info_long_id": 4066588972336828000
},
"limit": 1,
"singleBatch": true,
"$readPreference": {
"mode": "secondaryPreferred"
},
"$db": "userbehavior"
},
"planSummary": "COLLSCAN",
"numYields": 4655,
"locks": {
"Global": "r",
"Database": "r",
"Collection": "r"
},
"waitingForLock": false,
"lockStats": {
"Global": {
"acquireCount": {
"r": 4656
}
},
"Database": {
"acquireCount": {
"r": 4656
}
},
"Collection": {
"acquireCount": {
"r": 4656
}
}
}
}]
上面的信息还是非常有用的，我先为大家介绍下需要重点关注的字段的含义。（db.currentOp() — MongoDB Manual）
| 字段 | 含义 |
|---|---|
| client | 该操作是由哪个客户端发起的 |
| opid | 操作的唯一标识符（可以通过db.killOp(opid)命令直接终止该操作） |
| secs_running | 该操作的执行时间，单位为秒 |
| microsecs_running | 该操作的执行时间，单位为微秒 |
| ns | 执行该操作的集合 |
| op | 操作的类型（增删改查） |
| locks | 跟锁相关的信息 |
3、解决问题，分析原因
好了看到这里，基本上已经破案了，
"planSummary": "COLLSCAN"表示走了全表扫描、"secs_running": 33可以看到一个查询耗时33s，相当恐怖。"filter": { "user_common_info_long_id": 4066588972336828000 }指具体的查询条件。最后还是因为少加索引的锅。（之前做的新功能上线，mongo集合里新增了两个字段，同时根据新增字段的查询非常频繁，上线后忘了加索引...）
#添加索引
db.user_behavior.createIndex({user_common_info_long_id:1},{background:true, "name" : user_behavio_long_idx"})
这里
background:true表示命令在后台执行，"name" : user_behavio_long_idx"设定索引的名称，{user_common_info_long_id:1}指定了建立索引的字段，并按升序创建。创建索引后，CPU占用率回到了1%-10%，解决！
好了、本期就先介绍到这里，有什么需要交流的，大家可以随时私信我。😊
