先说一个发生在我这边的真实故事。有段时间公司管理后台的订单导出功能隔三差五就卡死用户点一次导出浏览器转圈半分钟数据库的 CPU 直接冲到 90% 以上。我排查了一圈最后在 MongoDB 的 system.profile 集合里抓到一条执行了 3000 多毫秒的查询扫描了 35 万条文档最后只返回 20 条结果典型的全表扫描。随手加了一个复合索引执行时间直接掉到 3 毫秒。那次排障之后我彻底体会到MongoDB 慢查询分析这件事profile 集合用好了性能瓶颈定位就是几分钟的事。这篇文章打算把这套方法完整讲一遍怎么开启 profile、怎么从 system.profile 里把慢查询捞出来、怎么解读关键字段、怎么结合 explain 做优化验证以及我在生产环境里踩过的坑。适合刚接手 MongoDB 的后端同学也适合已经会用 explain 但想系统化做性能巡检的 DBA。看完之后你至少能把“数据库怎么这么慢”这种模糊描述变成一条条可以直接执行的优化动作。1. 先把 profile 机制吃透它记录了什么、为什么用它1.1 profiling 的三档级别和 system.profile 的存储特性MongoDB 把记录慢查询的能力叫做 database profiling开启之后符合条件的操作会被写入 system.profile。system.profile 是一个 capped collection容量固定满了就自动覆盖最旧的记录。这就像行车记录仪只存最近一段时间的画面不会无限占磁盘。系统默认有三个级别level 0关闭不记录任何操作这是默认状态。level 1只记录执行时间超过阈值的操作阈值由 slowms 指定默认是 100ms。level 2记录所有操作不管快慢。level 2 我基本不建议在生产环境开。所有操作都记录包括读、写、管理命令很快会把集合写满并反复覆盖而且写日志本身就有开销。之前有一次在压测环境里开过 level 2TPS 高的时候 profile 集合每秒要写几千条记录写入造成的负载比慢查询本身还严重。生产环境只开 level 1配合合理阈值就够了。这里牵扯出一个很现实的问题system.profile 默认创建时分配的容量不一定够用。高流量业务下一个小容量的 capped 集合可能只保留几分钟的记录等你发现问题想回溯时数据早被覆盖了。建议在部署初期就评估一下用 db.system.profile.stats() 查看当前容量如果不够就要手动重建一个更大容量或合适出入的 profile 集合别等到排查时发现历史记录都没了。1.2 一条请求从“正常”到“被记录”发生了什么当你开启了 profilingMongoDB 会把执行时间超过 slowms 阈值的操作包装成一条 profile 文档写入 system.profile。这条文档里保存了操作类型 op、命名空间 ns、完整查询条件 query、执行耗时 millis、扫描文档数 docsExamined、扫描索引键数 keysExamined、返回行数 nreturned以及执行计划摘要 planSummary 等字段。这些字段就是我们判断性能瓶颈的核心依据。需要提醒的是每条 profile 记录本质上就是一个普通 JSON 文档你可以像查普通集合一样去查它。因为它是 capped 集合所以不需要担心日志无限膨胀它会自转覆盖。另外有个容易忽略的点MongoDB 的日志文件里也会输出 Slow query 信息和 system.profile 共用同一个 slowms 阈值但两者是独立的记录机制。我一般是两个都开。日志方便实时感知profile 方便做结构化统计和趋势分析。光靠人肉刷日志在高并发日志量下很难看到全貌。2. 实操开启 profile 并把配置固定下来2.1 三行命令快速开启和验证最快的方式是连接 MongoDB 后直接执行use admin db.setProfilingLevel(1, { slowms: 100 })执行后返回类似{ was : 0, slowms : 100, ok : 1 }的文档表示之前是 level 0现在已成功设为 level 1慢查询阈值是 100ms。查看当前状态用db.getProfilingStatus()返回结果里能看到当前级别和阈值。想确认 system.profile 实际大小执行db.system.profile.stats()这里要注意一个原则profiling level 是全局生效的不是“只记录某个库”。无论你在哪个库执行 setProfilingLevel最终都影响整个实例。因为 system.profile 存放在 admin 库记录范围覆盖所有数据库。有些人想只监控某个核心业务库结果发现所有库的慢查询都进来了反而被无关日志干扰。遇到这种情况后续分析时用 ns 字段过滤就好。等业务跑一段时间后看看有没有记录db.system.profile.find().sort({ ts: -1 }).limit(5).pretty()如果没有任何记录可能是业务里确实没有超过阈值的操作也可能是你选的阈值偏高。这时候不要急着调低继续往下分析。2.2 重启失效问题最终还是要写配置文件命令行设置的 profiling 是内存态MongoDB 重启后会恢复默认关闭状态。所以如果要做长期监控必须把配置写进 mongod 的配置文件。以常规 YAML 配置为例operationProfiling: mode: slowOp slowOpThresholdMs: 100mode 有三个可选值off 对应 level 0slowOp 对应 level 1all 对应 level 2。改完配置后重启 mongod再执行 db.getProfilingStatus() 验证是否生效。修改配置重启这件事要放在低峰期做尤其是副本集环境建议逐个节点滚动重启别直接把所有节点同时重启以免影响线上读写。这是生产环境最基本的操作纪律很多人都忽略了。关于 slowms 阈值的选择默认 100ms 看起来合理但也要看业务场景。如果业务查询本来就简单绝大多数操作都在 5ms 内完成那 100ms 阈值可能漏掉一些初期波动如果数据库本身压力大、慢查询很多一开始就把阈值设置成 10msprofile 集合里会被“正常慢”操作淹没真正需要关注的问题反而不明显。我习惯的做法是先按 100ms 跑一天用聚合统计看整体耗时分布再根据 Top10 的实际情况收紧到 50ms 或放宽到 200ms。这比拍脑袋定阈值靠谱得多。3. 从 system.profile 里把慢查询“挖”出来3.1 最常用的三种分析查询拿到 system.profile 里的记录后关键是怎么高效查询。我日常最常用的是下面几个。第一种直接看最近最慢的 20 条db.system.profile.find({ ns: { $ne: admin.system.profile }, millis: { $gt: 200 } }).sort({ ts: -1 }).limit(20).pretty()这里过滤掉了 ns 为 admin.system.profile 自身的写记录否则你查 profile 这个动作本身也会被记录下来干扰分析结果。第二种按集合维度做耗时汇总看哪张表消耗最高db.system.profile.aggregate([ { $match: { ns: { $ne: admin.system.profile }, millis: { $gt: 0 } } }, { $group: { _id: $ns, count: { $sum: 1 }, totalMillis: { $sum: $millis }, avgMillis: { $avg: $millis }, maxMillis: { $max: $millis } }}, { $sort: { totalMillis: -1 } }, { $limit: 10 } ])这个统计的价值在于在一段观察窗口里哪个集合的累积耗时最高哪个集合大概率就是拖垮整体响应速度的元凶。比如报表接口慢汇总后看到 report.orders 的 totalMillis 占了 80%那就顺着这个集合继续深挖。第三种按执行计划和集合组合统计快速定位哪些查询正在全表扫描db.system.profile.aggregate([ { $match: { ns: { $ne: admin.system.profile }, millis: { $gt: 100 } } }, { $group: { _id: { ns: $ns, planSummary: $planSummary }, count: { $sum: 1 } }}, { $sort: { count: -1 } }, { $limit: 20 } ])这一步可以快速把“大量 COLLSCAN 操作”识别出来。不同 MongoDB 版本的 profile 文档结构略有差异有的版本里 planSummary 字段不一定叫这个名字建议先在 collection 里 findOne 一条记录看看结构再写统计脚本不要拿着旧脚本直接跑。3.2 核心字段解读不要只会看 millis很多同学看慢查询只盯一个 millis 字段看到执行时间几千毫秒就兴奋马上跑到 explain 里看有没有索引。但如果能静下心读一下 profile 里的其它字段往往能绕过不少弯路。字段名含义分析要点ns被执行的命名空间格式是 库名.集合名先锁定最耗时的表op操作类型query/insert/update/remove/command慢的是读还是写query查询条件command 字段里可以看到完整命令确认查询条件是否合理millis操作耗时毫秒判断是否持续飙升docsExamined实际扫描的文档数远大于返回数说明选择性差或没用索引keysExamined扫描的索引键数量远大于返回数说明索引匹配精度不够nreturned实际返回的文档数量配合上面两个字段判断索引是否有效responseLength响应字节数过大往往是返回了不需要的大字段planSummary执行计划摘要比如 COLLSCAN 或 IXSCAN一屏看出是否全表扫描ts操作发生时间结合业务高峰期判断是否为规律性问题举个例子如果一条查询的 docsExamined 是 30 万nreturned 只有 20说明数据库扫描了 30 万条文档才过滤出 20 条结果问题大概率出在索引缺失或者索引选择错误。如果 keysExamined 也很大但 nreturned 很小那往往不是没建索引而是复合索引字段顺序和查询条件不匹配导致索引大量无效扫描。这两种情况的优化方向完全不一样一个是建索引一个是调整索引顺序。所以只凭一条毫秒数根本没法精准定位问题。4. 从慢查询到优化用 explain 把执行计划看清楚4.1 用 explain(executionStats) 还原执行计划从 system.profile 里拿到具体的慢查询语句后下一步是把这条语句原样复制出来在 shell 里手动加 explain 执行确认执行计划到底长什么样。命令长这样db.orders.find({ status: pending, userId: u123 }) .sort({ createdAt: -1 }) .limit(20) .explain(executionStats)输出内容很多但只看几个关键指标就够了executionStats.executionTimeMillis实际执行时间executionStats.totalDocsExamined扫描文档数executionStats.totalKeysExamined扫描索引键数executionStats.nReturned返回条数queryPlanner.winningPlan.stage执行阶段COLLSCAN、IXSCAN、FETCH、SORT 等如果看到stage: COLLSCAN说明查询没有使用任何索引这是最需要优先解决的一类问题。如果看到IXSCAN - FETCH - SORT说明已经用了索引但后面还是出现了 SORT 阶段。SORT 在某些情况下不一定是坏事但如果需要排序的数据量特别大SORT 的内存消耗和耗时都会很夸张这时要考虑是不是索引字段顺序可以覆盖排序条件。建议始终使用 explain(executionStats) 而不要用默认的 explain()因为默认模式下拿不到 totalDocsExamined 和 executionTimeMillis分析价值大打折扣。4.2 典型瓶颈从 profile 字段反推优化动作根据我观察到的常见情况慢查询基本可以归成几类。第一类COLLSCAN docsExamined 巨大。这是最典型、最容易解决的。解决方案就是创建合适的索引。比如上面那个查询条件是 status 精确匹配再加 createdAt 排序就创建复合索引db.orders.createIndex({ status: 1, createdAt: -1 })这里要注意复合索引字段顺序。原则是精确等值字段放前面排序字段放后面。如果索引建反了比如建了{ createdAt: -1, status: 1 }查询时 status 条件无法精确定位还是可能发生大量无效扫描keysExamined 会居高不下。第二类keysExamined 远大于 nreturned但 planSummary 显示已经走了 IXSCAN。这种情况经常不是“没有索引”而是索引没吃对。你可能会发现同一个集合上有好几个索引MongoDB 明明选了其中一个可扫描的键数量依然巨大。这时候要用 explain 看清楚获胜执行计划用的哪个索引再检查索引字段和查询条件是否匹配。也可以在查询语句里用 hint 手动指定索引做测试db.orders.find({ status: pending }) .hint({ status: 1, createdAt: -1 }) .explain(executionStats)第三类responseLength 超大。有些慢查询本身执行时间并不长但返回的响应体非常大导致网络传输和应用程序解析耗时上升用户体感依然是“卡”。这种情况在 profile 里的特征是 millis 可能只有几十毫秒但 responseLength 动辄几 MB。原因是 find 没有加 projection把文档里的大数组、大文本字段全返回了。优化方式很简单加一个字段白名单db.orders.find({ status: pending }, { _id: 1, orderNo: 1, totalAmount: 1 })第四类慢的是 update 或 remove 等写操作。写操作慢的原因和读不同经常跟锁竞争、批量更新范围过大有关。通过 profile 里 op:update 的记录配合 observed locks 字段可以看到是否长时间等待写锁。解决思路通常是把大事务拆成小批量一次不要处理几万条数据特别是业务高峰期尽量打散更新减少锁持有时间。第五类聚合命令触发内存限制或中间结果膨胀。MongoDB 的聚合框架里$group、$sort 等阶段默认最多使用 100MB 内存超过会报错。而且 $lookup、$unwind 这类操作会把中间结果放大很多倍。优化方向是尽量把 $match 前移先过滤数据再关联实在无法避免大数据量聚合时可以给 aggregate 加上{ allowDiskUse: true }但这只是缓解治标不治本。根本上还是减少进入聚合的文档量。5. 一次真实故障复盘和避坑清单5.1 完整复盘案例我印象很深的一次故障是某个报表接口每到下午两三点就开始变慢从原来的几百毫秒涨到四五秒。一开始排查网络和服务器负载都没问题后来在备节点上查了 system.profile发现report.orders集合里连续出现多条聚合命令millis 都在 2000ms 以上db.system.profile.find({ ns: report.orders, millis: { $gt: 500 } }).sort({ ts: -1 }).limit(5).pretty()我把其中一条 command 字段拿出来看发现里面有 $unwind 和 $lookup。这条聚合先把订单的 items 数组展开每个订单因此变成多行然后再用items.goodsId去关联商品表。一个订单如果有 30 个商品展开后就是 30 条中间结果再关联一次商品库数据量被放大了几十倍总耗时自然爆炸。我用 explain(executionStats) 验证后做了三个改动把 $match 前移先把 orders 集合限定在当天的时间范围内。把 $lookup 的关联条件在关联前先过滤一遍减少关联目标集合的数据扇出。去掉不必要的 $unwind改用 $reduce 或 $size 处理数组汇总。同时给商品表的关联字段建了索引。优化后同一条聚合的 millis 从 2000 多毫秒降到 40 毫秒totalDocsExamined 从几十万降到几千。这个案例说明慢查询分析不能只看表面语句要顺着执行计划追到数据模型是否合理有时候问题根本不在一张表而是聚合阶段的中间结果失控。5.2 常见问题速查表从踩坑中总结现象可能原因排查方式profile 命令设置后重启失效没有写入 mongod.conf把 operationProfiling 配置写进配置文件system.profile 很快被覆盖capped 集合容量太小stats() 查看容量必要时重建更大的集合开 level 2 后数据库整体变慢全量记录本身就带来写入开销生产环境用 level 1查 profile 时看到自己的监控查询监控操作也会被记录ns 过滤掉 admin.system.profiledocsExamined 很大但 keysExamined 小没命中索引走了 COLLSCANexplain 确认后创建合适索引keysExamined 也很大但 nreturned 少复合索引字段顺序和查询不匹配检查索引最左前缀调整字段顺序聚合命令超时或内存错误大数据量 $group/$sort 内存溢出加 allowDiskUse优化 pipeline 顺序我再特别提醒一个很少有人说的坑临时开启 level 2 后干完活一定要记得改回来。之前有同学在测试环境开 level 2 跑压测结束后忘关第二天所有接口都变慢查了半天才发现是 profile 集合每秒写入几百条记录在入口处就增加了不必要的开销。这种问题非常隐蔽它不会报错只会让你觉得数据库“好像哪里怪怪的”。所以每次临时开启 profiling都应该在心里过一遍这个级别要开多久什么时候恢复 level 1。如果让我说这几年来在 MongoDB 性能排查上的最大体会那就是不要等线上变慢了才去开 profile。慢查询分析应该成为日常巡检的一部分。我现在每个周一早上都会在备节点上查一次 admin 库的 system.profile把累计耗时 Top10 的查询导出来连同执行计划的指标一起存到独立的性能趋势集合里。这样能看到一个查询是不是在持续变慢而不是等它某天突然爆发。另一个小技巧是改动索引后不要只看优化当天的执行时间应该把同一查询在改动前后的 docsExamined 和 keysExamined 拉出来对比。这两个指标最能说明索引是否真正被用对了——哪怕 millis 受到机器负载影响会波动扫描行数不会说谎。