MongoDB慢查询一例
01 问题背景
今天在线上遇到了一个MongoDB的问题，这里记录一下。
场景：
1、监控报警某个业务的连接数很高，具体情况如下：
代码语言：javascript复制 ------------- --------- --- ------- ----------- ----------- -------- ---------
|HOST |STATE |LAG|VERSION|NODE_CONF |CONNECTIONS|MEM_USED|DISK_USED|
------------- --------- --- ------- ----------- ----------- -------- ---------
| | | | | | | | |
|10.xx.xxx.xxx|PRIMARY |0 |4.0.4 |P:1;D:0;H:0|1217/10000 |9.3GB |54G |
|10.xx.xxx.xxx|SECONDARY|0 |4.0.4 |P:1;D:0;H:0|53/10000 |9.3GB |53G |
|10.xx.xxx.xxx|SECONDARY|2 |4.0.4 |P:1;D:0;H:0|50/10000 |10.3GB |54G |
------------- --------- --- ------- ----------- ----------- -------- ---------
可以看到，Primary节点的连接数有1217，最大连接数是10000.
2、业务反馈某个节点的写入非常慢。超时严重。
02 排查过程
1、服务器层面
一般出现这种问题，首先需要排查的，就是服务器层面的问题，服务器层面的问题排除之后，再去看数据库层面的问题。
登录到MongoDB主库所在的服务器，查看服务器层面的监控，可以发现如下现象：
可以看到，服务器的CPU使用率异常，从10%以下上升到100%了；同时，服务器负载异常，从1上升到了900多。
这里，问题基本定位，就是这台服务器的问题，导致业务的响应时间变长，然后由于程序迟迟拿不到结果，所以发起重连，连接数也就自然上升了。
2、数据库层面
然后，我们来看看这台服务器上哪个进程使用的CPU最多。
使用top -c命令，查看当前进程，发现就是当前这个MongoDB占用的CPU最多。
现在问题，就转变成了排查这个MongoDB正在进行的操作，看看到底是什么原因导致的占用CPU这么高的。
先来看看这个MongoDB实例的状态：
代码语言：javascript复制mongostat
insert query update delete getmore command dirty used flushes vsize res qrw arw net_in net_out conn set repl time
*0 65 42 *0 8 316|0 4.4% 80.0% 0 14.7G 9.32G 0|808 2|128 518k 890k 1192 index PRI Dec 20 14:31:41.276
*0 26 15 *0 4 122|0 4.5% 80.0% 0 14.7G 9.32G 0|806 1|128 154k 268k 1208 index PRI Dec 20 14:31:45.328
*0 40 21 *0 7 159|0 4.5% 80.0% 0 14.7G 9.32G 0|790 1|128 228k 359k 1222 index PRI Dec 20 14:31:47.988
*0 134 132 *0 16 646|0 4.6% 80.0% 0 14.7G 9.32G 0|803 2|128 987k 1.32m 1213 index PRI Dec 20 14:31:49.494
*0 36 66 *0 4 150|0 4.7% 79.9% 0 14.7G 9.32G 0|814 3|127 218k 389k 1203 index PRI Dec 20 14:31:54.656
*0 46 90 *0 7 289|0 4.8% 80.0% 0 14.7G 9.32G 0|764 2|128 230k 336k 1239 index PRI Dec 20 14:31:57.625
*0 90 179 *0 8 379|0 4.8% 80.0% 0 14.8G 9.32G 0|791 2|127 490k 779k 1271 index PRI Dec 20 14:31:59.123
发现没有insert操作，大部分都是update操作。
然后根据这个update操作，查看这个MongoDB的日志，可以看到很多的update慢日志：
tail -f mongod.log | grep [0-9][0-9][0-9][0-9][0-9]ms
结果如下：
代码语言：javascript复制2021-12-20T14:34:10.052 0800 I WRITE [conn1573045] update db.tbl
command: { q: { unique_id: "community:9394 315186" }, u: { unique_id: "community:9394 315186", object_id: "9394 315186",
from: "community", tags: [], tag_scores: [], quality_score: 0.001, online: "1",
update_time: new Date(1639981985000), create_time: new Date(1639981323000) },
multi: false, upsert: true }
planSummary: COLLSCAN keysExamined:0 docsExamined:574333 nMatched:0 nModified:0 fastmodinsert:1
upsert:1 keysInserted:3 numYields:4510 locks:{ Global: { acquireCount: { r: 4512, w: 4512 } },
Database: { acquireCount: { w: 4512 } }, Collection: { acquireCount: { w: 4512 } } }
32618 ms
2021-12-20T14:34:10.160 0800 I WRITE [conn1573082] update db.tbl
command: { q: { unique_id: "community:9394 315187" },
u: { unique_id: "community:9394 315187", object_id: "9394 315187",
from: "community", tags: [], tag_scores: [], quality_score: 0.001, online: "1",
update_time: new Date(1639981986000), create_time: new Date(1639981377000) },
multi: false, upsert: true }
planSummary: COLLSCAN keysExamined:0 docsExamined:574379 nMatched:0 nModified:0 fastmodinsert:1
upsert:1 keysInserted:3 numYields:4505 locks:{ Global: { acquireCount: { r: 4507, w: 4507 } },
Database: { acquireCount: { w: 4507 } }, Collection: { acquireCount: { w: 4507 } } }
30591 ms
可以看到，MongoDB的慢日志有很多时间超过30s的，扫描方法是全表扫描，扫描行数有57w行左右。
同时，update更新的条件是unique_id=“community:9394 315187”
到这里，问题可以定位了。
这个集合中的unique_id字段没有索引，但是却根据这个字段进行更新，导致所有的更新匹配都会扫描全表。而业务侧是今天才大量上线这个update语句，所以是突然大量超时。
03 解决办法
这个问题的解决方案，其实也比较简单，就是给对应的数据库集合添加索引即可：
db.coll.createIndex({ "unique_id": 1 },{background:true});
注意，这里使用了background后台添加，是为了不阻塞前台的业务访问。
添加了索引之后，业务反馈响应超时问题解决，查看相关监控，监控显示如下：
可以看到，CPU使用率从100%降低到了10%以下，而负载从800多，降低到了1左右。
再来看连接数：
代码语言：javascript复制 ------------- --------- --- ------- ----------- ----------- -------- ---------
|HOST |STATE |LAG|VERSION|NODE_CONF |CONNECTIONS|MEM_USED|DISK_USED|
------------- --------- --- ------- ----------- ----------- -------- ---------
| | | | | | | | |
|10.xx.xxx.xxx|PRIMARY |0 |4.0.4 |P:1;D:0;H:0|86/10000 |9.5GB |54G |
|10.xx.xxx.xxx|SECONDARY|0 |4.0.4 |P:1;D:0;H:0|58/10000 |9.5GB |54G |
|10.xx.xxx.xxx|SECONDARY|0 |4.0.4 |P:1;D:0;H:0|51/10000 |10.4GB |54G |
------------- --------- --- ------- ----------- ----------- -------- --------- 连接数也从1217变成了86个，回归正常。
至此，问题得到了解决。
04 总结
这个问题本身比较简单，处理方法也比较简单，但是，这个排查并定位问题的过程值得总结，其实任何一种数据库问题的排查，都可以采用这种方法，无论是MySQL、MongoDB、Redis、MC、还是TiDB，我们尝试总结一下：
1、搞清楚问题背景，此时的业务现象；
2、搞清楚当前出问题数据库的架构，确认是主库问题还是从库问题，如果是分布式集群，要先定位到是哪一个节点的问题；
3、排查当前数据库所在的服务器的情况，例如CPU、内存、磁盘、网卡流量、负载等
4、如果服务器不存在问题，进一步定位服务器上的数据库状态，先确定数据库目前正在进行的操作。这里可以借助监控信息或者数据库本身自带的一些命令。
5、定位出具体的数据库操作，联系业务方解决，通常给出优化建议即可。
这个问题中，其实只是一个小小的索引没有创建，就会导致CPU的负载飙升800多倍，其实还是挺吓人的。在数据量小的时候，加不加索引，其实问题不大，但是当数据量很大，访问频繁的时候，没有索引就会导致灾难。
对于线上环境，任何一个隐患都不能放过，以上。
