描述
- 场景描述：用户网页上，查询测试表数据，下滑时加载下一页。
- 测试表数据：100w左右，数据量可以说是平平无奇。
- 查询条件：db.test.find({_id:xxxxxx,status:1}).sort({beginTime:-1}).hint({beginTime:1})
先说下结论
这个接口一直存在大于两秒的查询，当请求量上升时，类似的慢查询任务会堆积在mongo数据库服务，CPU所有的内核全部被占用，进而影响到这个库里所有的读写操作，造成全局阻塞。
在后续的慢查询分析里，通过查看docsExamined的值，可以查看到这个查询扫描了97w的文档。该值越大，请求所占用的CPU开销越大，keysExamined同理。
现象
Mongo服务监控图
慢查询日志
2023-01-05 14:34:45 xx.xx.xx.xx 2023-01-05T14:34:45.211+0800 I COMMAND [conn6666] command topic.test command: find { find: "test", filter: { topicId: ObjectId('60d12355bcad23531df7'), status: 0 }, projection: { $sortKey: { $meta: "sortKey" } }, sort: { beginTime: -1 }, hint: { beginTime: -1 }, limit: 8, shardVersion: [ Timestamp 1000|20, ObjectId('56912355bcad23531897') ] } planSummary: IXSCAN { beginTime: -1 } keysExamined:970102 docsExamined:970102 cursorExhausted:1 numYields:7737 nreturned:3 reslen:1695 locks:{ Global: { acquireCount: { r: 15476 } }, Database: { acquireCount: { r: 7738 } }, Collection: { acquireCount: { r: 7738 } } } protocol:op_command 121129ms
分析
监控
从监控图中可以看出，读写操作都在主节点执行，从节点基本处于闲置状态，这是一个优化点。
日志
这里详细分析一下前面提到的慢查询日志
- I：代表info日志，还有F(Fatal),E(Error),W(warn),D(Debug);
- COMMAND:数据库命令，CURD等；比较常见的还有QUERY(查询相关)，INDEX(索引操作相关)，SHARDING(分片行为相关)等；
- command：具体的操作命令细节；【find { find: "test", filter: { topicId: ObjectId('60d12355bcad23531df7'), status: 0 }, projection: { sortKey: { meta: "sortKey" } }, sort: { beginTime: -1 }, hint: { beginTime: -1 }, limit: 8, shardVersion: [ Timestamp 1000|20, ObjectId('56912355bcad23531897') ] } 】
- planSummary：命令执行计划的简要说明，当前使用了 beginTime 这个字段的索引。如果是全表扫描，则是COLLSCAN；【IXSCAN { beginTime: -1 } 】
- keysExamined：为找出最终结果,MongoDB扫描了索引中key的数量；【970102】
- docsExamined：找出最终结果,MongoDB扫描了文档的数量；【970102】
- cursorExhausted：本次查询中游标耗尽的次数；【1】
- numYields：一个计数器，它报告操作已屈服以允许其他操作完成的次数。一般发生在需要访问的数据尚未被完全读取到内存中，MongoDB会优先完成在内存中的操作；【7737】
- nreturned：该操作最终返回文档的数量；【3】
- reslen：结果返回的大小，单位为bytes，该值如果过大，则需考虑limit()等方式减少输出结果；【1695】
- locks：在操作中产生的锁，锁的种类有多种，下面是具体每一种锁请求锁的次数；【{ Global: { acquireCount: { r: 15476 } }, Database: { acquireCount: { r: 7738 } }, Collection: { acquireCount: { r: 7738 } }】
- protocol：消息的协议；【op_command】
- millis：从 MongoDB 操作开始到结束耗费的时间，单位为ms；【121129ms】
从慢查询日志里，可以看出这条查询请求使用到了范围索引【IXSCAN { beginTime: -1 }】，扫描索引数量为970102，扫描文档数量为970102，基本是做了全表扫描，beginTime索引没有产生预期的作用。
优化建议
- 添加读偏好【readPreference】设置，把读请求转移到从节点，主节点只处理写请求,readPreference=secondaryPreferred；
- 针对这个查询请求，添加联合索引，缩小扫描范围；
- 添加时间范围，比如下一页的起始时间，beginTime < xxxx，避免将同一个条件下面符合状态条件的数据全部加载到内存中，进行排序抽选；
- 热点数据添加缓存，避免大量重复查询请求下沉到数据库；
