simon·4 years ago

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

Untitled

维护与防范

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"
  }
}