技术干货 | MongoDB 新特性 Mirrors Reads Bug 发现及分析

laomugua
发布于 2023-2-2 14:55
浏览
0收藏

背景


Mongo 组件持续运营过程中,发现“断言”异常,在排除人为操作和客户端异常等噪音后,仍然广泛分布在4系版本中。疑似有大鱼,于是集中力量专项治理。经分析,发现 Mongo Core Bug 一项,Mongo Shell Bug 一项,已提交 issue,并得到官网确认。其中 SERVER-72532 影响了4.4.11+,5.0.4+, 6.0.0+, 6.2.0-rc4+版本,属于影响范围较大的重要发现,官方暂未发布修复版本。其中 MONGOSH-1357 官方已确认,在版本1.6.2进行修复。下面具体描述问题的分析过程。


定位问题


通过对线上 MongoDB 集群构建告警监控体系,其中一套线上集群持续发生“客户端断言数量”告警,告警信息如下:

内容:监控点名称:MongoDB-断言数量;总告警条数:45。详细:

[实例:shard1_38_27001,主机:XXX,期望值:0,当前值:8];

[实例:shard1_39_27001,主机:XXX,期望值:0,当前值:8];

[实例:shard2_40_27002,主机:XXX,期望值:0,当前值:4];

[实例:shard2_41_27002,主机:XXX,期望值:0,当前值:8];

[实例:shard2_42_27002,主机:XXX,期望值:0,当前值:9];

[实例:shard3_44_27003,主机:XXX,期望值:0,当前值:10];

[实例:shard3_45_27003,主机:XXX,期望值:0,当前值:10];
……


问题分析


问题分析主要从 MongoDB 的指标、日志、源码三个方面进行分析。其中指标方面主要从访问量、主机、集群各项指标对比分析,尝试找到告警指标与其它监控指标的关联关系。日志方面主要找到导致发生异常的日志详细信息。源码方面主要基于指标、日志分析源码中的问题。


3.1 指标分析


通过对告警信息、监控指标的分析得出以下结论:

  • 通过告警信息可以发现,每个分片每秒都有10个左右的断言,10分钟就是6000个断言,这项指标明显偏高,而且判断不会是由于人为操作错误导致的异常,大概率是应用程序或其它 MongoDB 进程导致。
  • 通过告警信息可以发现,发生断言数告警的节点均为各分片的从节点,主节点未发生告警,而应用程序不连从节点,在排除了 Exporter 嫌疑后,基本确定是 MongoDB 内部组件引起的告警。
  • 通过分析监控指标发现,集群的断言数与应用的操作数趋势一致。由此可以初步判断由于应用的 CRUD 操作触发了集群内部的异常。


3.2 日志分析


默认的日志级别未打印出有效的异常信息,因此在某个分片的主、从节点分别执行db.setLogLevel(1)命令,将日志级别调高后,抓取更详细的信息如下:

{\”t\”:{\”$date\”:\”2023-01-04T16:02:45.079+08:00\”},\”s\”:\”I\”,  \”c\”:\”NETWORK\”,  \”id\”:51800,   \”ctx\”:\”conn141332\”,\”msg\”:\”client metadata\”,\”attr\”:{\”remote\”:\”主节点IP:51588\”,\”client\”:\”conn141332\”,\”doc\”:{\”driver\”:{\”name\”:\”NetworkInterfaceTL\”,\”version\”:\”4.4.14\”},\”os\”:{\”type\”:\”Linux\”,\”name\”:\”CentOS Linux release 7.6.1810 (Core) \”,\”architecture\”:\”x86_64\”,\”version\”:\”Kernel 3.10.0-957.el7.x86_64\”}}}}

{\”t\”:{\”$date\”:\”2023-01-04T16:02:45.080+08:00\”},\”s\”:\”I\”,  \”c\”:\”ACCESS\”,   \”id\”:20250,   \”ctx\”:\”conn141332\”,\”msg\”:\”Authentication succeeded\”,\”attr\”:{\”mechanism\”:\”SCRAM-SHA-256\”,\”speculative\”:true,\”principalName\”:\”__system\”,\”authenticationDatabase\”:\”local\”,\”remote\”:\”主节点IP:51588\”,\”extraInfo\”:{}}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”-\”,        \”id\”:23074,   \”ctx\”:\”conn141332\”,\”msg\”:\”User assertion\”,\”attr\”:{\”error\”:\”CommandNotFound: no such command: \’shardVersion\’\”,\”file\”:\”src/mongo/db/service_entry_point_common.cpp\”,\”line\”:1361}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”COMMAND\”,  \”id\”:21966,   \”ctx\”:\”conn141332\”,\”msg\”:\”Assertion while executing command\”,\”attr\”:{\”command\”:\”shardVersion\”,\”db\”:\”orderdb\”,\”error\”:\”CommandNotFound: no such command: \’shardVersion\’\”}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”I\”,  \”c\”:\”COMMAND\”,  \”id\”:51803,   \”ctx\”:\”conn141332\”,\”msg\”:\”Slow query\”,\”attr\”:{\”type\”:\”command\”,\”ns\”:\”orderdb.$cmd\”,\”command\”:\”unrecognized\”,\”numYields\”:0,\”ok\”:0,\”errMsg\”:\”no such command: \’shardVersion\’\”,\”errName\”:\”CommandNotFound\”,\”errCode\”:59,\”locks\”:{},\”protocol\”:\”op_msg\”,\”durationMillis\”:0}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”QUERY\”,    \”id\”:22790,   \”ctx\”:\”conn141332\”,\”msg\”:\”Received interrupt request for unknown op\”,\”attr\”:{\”opId\”:3652609564}}

*注意:日志抓取后,记得执行db.setLogLevel(0)恢复日志级别。

相似的日志只在分片的从节点发生,主节点并没有类似的日志,通过分析日志初步得出以下结论:

  • 导致 User asserts 指标告警的原因是 MongoDB 接收到了不支持的命令:shardVersion。
  • 发出 shardVersion 命令的是主节点 IP:51588,根据部署架构,该节点是 shard13 分片的主节点一个随机端口,因此该主节点是作为客户端主动向从节点发出了一个 MongoDB 不支持的操作命令 shardVersion。
  • 代码 src/mongo/db/service_entry_point_common.cpp 1361 行,命令解析失败确实会触发 user asserts 指标一直上涨。
  • 基于对 MongoDB 特性的掌握,主从节点之间主要有以下几种情况会发生交互,一是互发心跳,二是数据同步,三是数据预热,得出以下结论:
  • 互发心跳方面,从日志中未显示任何心跳信息,且如果心跳包解析异常会触发主从节点切换,而实际情况集群整体运行稳定,因此排除心跳包解析异常的可能性,排除。
  • 主从数据同步方面,4.4版本对主从数据同步的方式确实有优化,在4.4以上版本,从节点会以订阅的方式感知主节点的 oplog 变化,当主节点发生写操作时,会将 oplog 源源不断的推送到从节点,而4.4以下版本是从节点通过长轮询的方式主动拉取主节点的 oplog。因此,数据同步均是从节点作为客户端主动连接主节点,与日志信息不符,排除。
  • 数据预热方面,4.4版本新增了主、从节点预热特性,通过查阅官方文档,主节点在发生 count、distinct、find、findAndModify、update 操作时,会向从节点主动发起数据预热,即主节点会主动连接从节点按一定的比例进行指令推送,符合现象,因此将排查方向锁定在数据预热部分。


3.3 源码分析


通过以上指标、日志的分析初步锁定在主节点发生 count、distinct、find、findAndModify、update 操作时,主节点会主动将数据推送给从节点进行预热。对比分析4.4版本与4.2版本代码发现 count、distinct、find、findAndModify、update 命令在4.4.11版本发生了变更。在4.4.11版本组装请求时,添加了 shardVersion 命令。在 write_commands.cpp 拼接请求时 shardVersion 被错误地写在请求的第一个字段,导致 shardVersion 被 MongoDB 解析成一条命令而导致解析失败。

if (const auto& shardVersion = _commandObj.getField(\”shardVersion\”);

    !shardVersion.eoo()) {

    bob->append(shardVersion);

}

bob->append(\”find\”, _commandObj[\”update\”].String());

extractQueryDetails(_updateOpObj, bob);

bob->append(\”batchSize\”, 1);

bob->append(\”singleBatch\”, true);


3.4 实操验证


通过以上分析,初步确认是由于4.4版本引入的主从节点数据预热新特性导致的命令解析失败。为了验证这个结论,尝试通过禁用数据预热来观察 user asserts 是否持续上涨。执行命令:

db.adminCommand( {

  setParameter: 1,

  mirrorReads: { samplingRate: 0.0 }

} )

持续观察 user asserts 情况可以看出 user asserts 不再上涨。

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

启用数据预热并恢复预热比例为默认值 0.01,持续观察 user asserts 情况可以看出 user asserts 持续上涨。

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007219, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007241, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007257, rollovers: 0 }

到目前为止,通过分析我们已经可以确定是4.4版本 MongoDB 数据预热特性引发的内核的 Bug 导致命令解析失败,进而导致 user asserts 指标持续告警。接下来需要在官方社区上报 issue。


3.5 开源社区


MongoDB 有单独的 JIRA 系统来管理社区报告的缺陷,地址:https://jira.mongodb.org。本次发现的 issue 属于 MongoDB Core 级别的 Bug,另外,在禁用数据预热特性时,发现所使用的客户端工具 mongosh 1.6.0 版本禁用失败,报错信息如下:

db.adminCommand( {

…   setParameter: 1,

…   mirrorReads: { samplingRate: 0.0 }

… } )

MongoServerError: BSON field \’mirrorReads.samplingRate\’ is the wrong type \’int\’, expected type \’double\’

通过客户端工具 mongo 执行成功,因此判断出客户端工具 mongosh 1.6.0 在进行小数处理时也存在缺陷,因此一共创建了两个 issue,分别是:

并且均得到了官方的有效确认。其中 SERVER-72532 影响了4.4.11以上, 5.0.4以上, 6.0.0以上, 6.2.0-rc4以上版本,属于影响范围较大的重要发现,并且修复版本官方暂未确定。MONGOSH-1357 官方已确认在版本 1.6.2 进行修复。


3.6 影响范围


数据预热属于一个从节点在备生主时性能优化的特性,对集群整体运行及应用使用不构成影响。主要影响数据预热特性及运维监控:

  • 影响目前生产环境4.4.14版本分片集群 update  操作的数据预热,即主节点执行 update 操作,从节点无法对该操作的数据进行预热。
  • 影响 user asserts 指标的监控,可能导致例如认证失败、连接失败等应用使用方式的问题淹没在大量的 user asserts 告警中。


解决方法


  • 方法一:待官方发布修复版本后,进行版本升级,替换程序,滚动重启即可。
  • 方法二:官方建议可以在每个节点禁用数据预热特性,在每个节点执行命令:

db.adminCommand( {

  setParameter: 1,

  mirrorReads: { samplingRate: 0.0 }

} )

方法三:官方建议可以在每个节点禁用数据预热特性,滚动重启每个 MongoDB 进程,加入–setParameter mirrorReads=\'{samplingRate: 0}’启动参数。


文章转载自公众号:Mongoing中文社区

分类
标签
已于2023-2-2 14:55:35修改
收藏
回复
举报
回复
    相关推荐