Mongo CPU 过载调查及日志

Mongo CPU 过载调查及日志#

Created: June 22, 2021 5:52 PM

现象#

生产环境主库出现周期性 (04:05, 04:15, 07:05, 07:15, 11:05) 和非周期 (04:15–04:30， 11：05-11：15) CPU 利用率 5 分钟内超过 80%。

由于 CPU 超时是周期性，并且是非连续性的。因此合理怀疑是定时任务出现了问题。
根据 AWS EC2 上的预警时间去筛选相关的定时任务。

CPU 过载的客观原因#

全表扫描 (collection scan)#

What：COLLSCAN 全集合 / 表扫描，CPU 高消耗操作，会对表内或库内所有的记录扫描一遍，按照条件过滤。在 profile 集合或日志中发现 COLLSCAN 关键词，并且此操作比较频繁，则需要针对查询字段建立索引来优化。
How to locate: 可以通过 Profile 中的 planSummary 参数来判断是否发生了慢查询全表搜索。
How to address: 建立合理的索引

不合理索引#

What：不合理的索引会造成查询时扫描过多的索引，造成 CPU 高开销。
How to locate: 可以通过 system.profile 或者 Query Plans 的 planSummary 值为 IXSCAN 来定位是索引查询，并根据 keysExamined 来确认索引是否合理。
How to address：建立合理的索引

大数据量排序#

What: 当查询时的排序请求无法通过索引完成时，Mongo 会将数据放入到内存中排序，如果数据量过大会造成 CPU 过高。
How to locate: 当你在 system.profile 集合发现 SORT 关键字时，就可以考虑通过索引来优化排序。当请求包含排序阶段时， system.profile 里的 hasSortStage 字段会为 true。
How to address: 建立用于排序的索引

超出服务能力#

当如上几大问题全部排查完了，所有的 query 和索引都是科学的，那么说明服务的容量跟不上业务的体量了。
此时需要考虑升级配置。

Mongo 如何科学得建立索引

多看文档（[https://docs.mongodb.com/manual/indexes/]）
区分度高：distinc value count/total value count
无 Null 值：null 不建立索引
高频用于更新、查询 filter
升序、降序：
- 单字段索引中，升降序效果一样，因为 mongo 的索引是排序后向上下移动查询的。
- 在联合索引中，第二个索引字段的升降序就会影响查询效果了。例如第二个字段是订单时间，那么降序索引可以在更新订单时更快的锁定订单。
不可以盲目的建立索引，索引也有建立和插入时的创建成本。
这个话题太大，之后展开

监控及发现上述问题#

CurrentOp 当前操作信息#

高峰时期，使用 db.currentOp () 对超频 DB 进行状态检查，返回值的含义见 ([https://docs.mongodb.com/manual/reference/command/currentOp/#currentop-output-fields])

Profiler 性能分析日志#

Mongo 查询性能日志收集功能，默认关闭。由于对数据库性能有轻微的影响，因此推荐只在预发环境中开启。
主要功能是将数据库命令及其运行信息存储到每个 db 下的 system 文件夹 profile collection 中，这个 collection 的大小是固定的，超出设定大小后，自动删除旧日志，目前来看，最多可以存放最近 950 条记录 (感谢对账的大规模慢查询)。
Profiler 是日志版的 currentOp, 因为两者的返回参数是完全一样的。
Profiler 可以通过 db.setProfilingLevel (level) 来设置，level 有三级：0 (关闭)，1 (根据slowms阈值来筛选记录，slowms 为操作运行的毫秒数)，2 (记录所有操作日志)。
可以通过 db.getProfilingStatus () 来获取当前 db 的 Profiler 设置。

着重注意几个参数#

secs_running

操作运行的时间，秒级别

microsecs_running

操作运行的时间，毫秒级别
多久算是慢？
- Mongo 默认是 100ms 以上的查询就是慢查询，实际情况下，我们有 30s 的全表扫描查询。因此，我先设置为 200，最后可以根据业务复杂度讨论得出。

planSummary

COLLSCAN： 全表扫描
IXSCAN { field_name: 1 }：索引查询 内部标注用了什么索引
IDHACK： 主键索引查询 跳过其他的查询 plan，根据主键提供更优的查询，出现在查询 query 中有_id 值时

keysExamined

用于判断对这个查询而言，现有的索引是否合理。
表示一次查询完成前扫描了多少索引，值越大，CPU 开销越大

定位问题代码#

周期性#

04:05 (5 分钟均值，因此 04:00 起，UTC+8=12:05)

sync_transaction_data
任务 A (4 小时一次)(主要是 MySQL Membership 读取，及 Redis 中的 api db 写入)

04:15(12:15)

任务 B

07:05(15:05)

sync_transaction_data(下午三点第二次)
任务 C (主要操作 MySQL 读库)

11:05(19:05)

sync_transaction_data(晚上七点第三次)
任务 C

非周期性#

(04:15–04:30， 11：05-11：15)，根据时间来看，应该是sync_transaction_data的后续问题
但仍旧可以用profile围观一下

其他可能原因#

排除了周期及非周期的问题，如果还没有解决，就继续研究。

实践#

开启 Freeze 环境中的 Profile，设置为 1，并定阈值为 200
打开 Flower 监控异步任务运行情况
打开 AWS CloudWatch 监控 CPU 使用情况
进入 Freeze Shell 执行 sync_transaction_data.delay ()
打开 MongoDB，查看 Bill 下的 profile collection 中的慢查询日志
发现 900 多条这类日志 [1], 可以注意到这个是一个全表扫描。
三个字段 transaction_time, channel, settlement_sign，后两个一个是只有 5 种类别的枚举字段，一个是只有 0 和 1 的 Boolean 字段。区分度太低。只有第一个 transaction_time 字段适合。
加上索引后，CPU 占用率用 99.9% 降到 3%，异步任务时间从 900s 降到 19s

维护与防范#

Freeze 环境打开 Profile 性能监控
定期检查并处理慢查询

{
  "op":"query",
  "ns":"bill.transaction",
  "keysExamined":0,
  "query":{  
     "find":"transaction",
     "filter":{  
        "transaction_time":{  
           "$gte":{"$date":"2018-05-20T23:00:00.000+0000"},
           "$lte":{"$date":"2018-05-21T22:59:59.999+0000"}},
        "channel":"非再惠渠道",
        "settlement_sign":{  
           "$in":[1]}}
  },
  "docsExamined":2882636,
  "cursorExhausted":true,
  "numYield":22635,
  "nreturned":0,
  "responseLength":104,
  "protocol":"op_query",
  "millis":15131,
  "planSummary":"COLLSCAN",
  "execStats":{
     "stage":"COLLSCAN",
     "nReturned":0,
     "executionTimeMillisEstimate":14727,
     "works":2882638,
     "advanced":0,
     "needTime":2882637,
     "needYield":0,
     "saveState":22635,
     "restoreState":22635,
     "isEOF":1,
     "invalidates":0,
     "direction":"forward",
     "docsExamined":2882636
  },
  "ts":{
     "$date":"2018-05-23T12:30:42.539+0000"
  }
}